search

espressif / esp-hosted

Hosted Solution (Linux/MCU) with ESP32 (Wi-Fi + BT + BLE)
Other
675 stars 158 forks source link

esp_hosted_ng: Getting MAC times out with esp_hosted_ng & ESP32-S3 #333

Closed sergey-suloev closed 7 months ago

sergey-suloev commented 7 months ago

Hello, I am trying esp_hosted_ng with a ESP32-S3 module. I made some minor changes to your code in order to load the linux driver via device tree. See https://github.com/sergey-suloev/esp-hosted/tree/master/esp_hosted_ng/host. But I can only receive a bootup event , the "get MAC" command gets timed out. Can you give any advice on how to proceed ? Here is the log I am getting:

[ 8.655700] esp32_spi:esp_init: esp_init: enter [ 8.660724] esp32_spi spi0.0: Probing ESP32 SPI-driver... [ 8.666350] esp32_spi spi0.0: Hardware reset [ 8.882552] esp32_spi spi0.0: ESP32 peripheral is registered to SPI bus [0], chip select [0], SPI Clock [30], SPI mode [0x02] [ 8.894346] sun50i-a64-pinctrl 1c20800.pinctrl: supply vcc-ph not found, using dummy regulator [ 9.110220] esp32_spi spi0.0: Probe success. [ 9.114789] esp32_spi:esp_init: esp_init: ret=0 [ 10.346525] esp32_spi:process_esp_bootup_event: Received ESP bootup event [ 10.353395] esp32_spi:process_event_esp_bootup: Bootup Event tag: 3 [ 10.359721] esp32_spi:esp_validate_chipset: Chipset=ESP32-S3 ID=09 detected over SPI [ 10.367700] esp32_spi:process_event_esp_bootup: Bootup Event tag: 2 [ 10.374018] esp32_spi:process_event_esp_bootup: Bootup Event tag: 0 [ 10.380408] esp32_spi:process_event_esp_bootup: Bootup Event tag: 1 [ 10.386793] esp32_spi:process_fw_data: ESP chipset's last reset cause: [ 10.395922] esp32_spi:print_reset_reason: POWERON_RESET [ 10.402828] esp32_spi:check_esp_version: ESP Firmware version: 1.0.3 [ 10.419129] esp32_spi:esp_reg_notifier: Driver init is ongoing [ 11.647084] dwmac-sun8i 1c30000.ethernet eth0: Link is Up - 100Mbps/Full - flow control rx/tx [ 15.582193] esp32_spi:wait_and_decode_cmd_resp: Command[3] timed out [ 15.588626] esp32_spi:cmd_get_mac: wait_and_decode_cmd_resp(priv, cmd_node) failure, ret: -22 [ 15.597219] esp32_spi:esp_add_card: esp_add_network_ifaces(adapter) failure, ret: -1 [ 15.605108] esp32_spi:process_event_esp_bootup: network iterface init failed

mantriyogesh commented 7 months ago

What is the git commit you use at both, ESP and host? Also, can you please attach the ESP side log?

sergey-suloev commented 7 months ago

ESP-ROM:esp32s3-20210327 Build:Mar 27 2021 rst:0x1 (POWERON),boot:0x8 (SPI_FAST_FLASH_BOOT) SPIWP:0xee mode:DIO, clock div:1 load:0x3fce3818,len:0x16e8 load:0x403c9700,len:0x4 load:0x403c9704,len:0xbb8 load:0x403cc700,len:0x2e28 entry 0x403c98f0 I (27) boot: ESP-IDF d3c99ed3-dirty 2nd stage bootloader I (27) boot: compile time Feb 13 2024 13:13:44 W (27) boot: Unicore bootloader I (30) boot: chip revision: v0.1 I (34) boot.esp32s3: Boot SPI Speed : 80MHz I (39) boot.esp32s3: SPI Mode : DIO I (44) boot.esp32s3: SPI Flash Size : 4MB I (49) boot: Enabling RNG early entropy source... I (54) boot: Partition Table: I (58) boot: ## Label Usage Type ST Offset Length I (65) boot: 0 nvs WiFi data 01 02 00009000 00004000 I (72) boot: 1 otadata OTA data 01 00 0000d000 00002000 I (80) boot: 2 phy_init RF data 01 01 0000f000 00001000 I (87) boot: 3 factory factory app 00 00 00010000 00100000 I (95) boot: 4 ota_0 OTA app 00 10 00110000 00100000 I (102) boot: 5 ota_1 OTA app 00 11 00210000 00100000 I (110) boot: End of partition table I (114) boot: Defaulting to factory image I (119) esp_image: segment 0: paddr=00010020 vaddr=3c080020 size=22f10h (143120) map I (153) esp_image: segment 1: paddr=00032f38 vaddr=3fc98f00 size=042b0h ( 17072) load I (157) esp_image: segment 2: paddr=000371f0 vaddr=40374000 size=08e28h ( 36392) load I (167) esp_image: segment 3: paddr=00040020 vaddr=42000020 size=7ad90h (503184) map I (257) esp_image: segment 4: paddr=000badb8 vaddr=4037ce28 size=0c080h ( 49280) load I (277) boot: Loaded app from partition at offset 0x10000 I (277) boot: Disabling RNG early entropy source... I (289) cpu_start: Unicore app D (289) flash HPM: HPM with dummy, status is 3 I (289) cpu_start: Pro cpu up. I (290) cpu_start: Single core mode D (302) clk: RTC_SLOW_CLK calibration value: 4014566 I (311) cpu_start: Pro cpu start user code I (311) cpu_start: cpu freq: 240000000 Hz I (311) cpu_start: Application information: I (314) cpu_start: Project name: network_adapter I (319) cpu_start: App version: release/ng-v1.0.2-186-g240c10e- I (326) cpu_start: Compile time: Feb 13 2024 13:13:41 I (333) cpu_start: ELF file SHA256: d96af30d5cac8f25... I (339) cpu_start: ESP-IDF: d3c99ed3-dirty I (344) cpu_start: Min chip rev: v0.0 I (349) cpu_start: Max chip rev: v0.99 I (354) cpu_start: Chip rev: v0.1 D (358) memory_layout: Checking 6 reserved memory ranges: D (364) memory_layout: Reserved memory range 0x3fc84000 - 0x3fc98f00 D (370) memory_layout: Reserved memory range 0x3fc98f00 - 0x3fca0998 D (377) memory_layout: Reserved memory range 0x3fceee34 - 0x3fcf0000 D (383) memory_layout: Reserved memory range 0x40374000 - 0x40388f00 D (389) memory_layout: Reserved memory range 0x600fe000 - 0x600fe010 D (396) memory_layout: Reserved memory range 0x600fffe8 - 0x60100000 D (402) memory_layout: Building list of available memory regions: D (409) memory_layout: Available memory region 0x3fca0998 - 0x3fcb0000 D (415) memory_layout: Available memory region 0x3fcb0000 - 0x3fcc0000 D (422) memory_layout: Available memory region 0x3fcc0000 - 0x3fcd0000 D (428) memory_layout: Available memory region 0x3fcd0000 - 0x3fce0000 D (435) memory_layout: Available memory region 0x3fce0000 - 0x3fce9710 D (441) memory_layout: Available memory region 0x3fce9710 - 0x3fceee34 D (448) memory_layout: Available memory region 0x3fcf0000 - 0x3fcf8000 D (455) memory_layout: Available memory region 0x600fe010 - 0x600fffe8 I (461) heap_init: Initializing. RAM available for dynamic allocation: D (469) heap_init: New heap initialised at 0x3fca0998 I (474) heap_init: At 3FCA0998 len 00048D78 (291 KiB): DRAM I (480) heap_init: At 3FCE9710 len 00005724 (21 KiB): STACK/DRAM D (487) heap_init: New heap initialised at 0x3fcf0000 I (492) heap_init: At 3FCF0000 len 00008000 (32 KiB): DRAM D (498) heap_init: New heap initialised at 0x600fe010 I (503) heap_init: At 600FE010 len 00001FD8 (7 KiB): RTCRAM D (509) intr_alloc: Connected src 39 to int 2 (cpu 0) D (515) spi_flash: trying chip: issi D (518) spi_flash: trying chip: gd I (521) spi_flash: detected chip: gd I (526) spi_flash: flash io: dio W (530) spi_flash: Detected size(16384k) larger than the size in the binary image header(4096k). Using the size in the binary image header. D (543) cpu_start: calling init function: 0x42061a8c D (548) cpu_start: calling init function: 0x4206156c D (553) cpu_start: calling init function: 0x420247b0 D (558) cpu_start: calling init function: 0x42001b68 D (563) cpu_start: calling init function: 0x4200712c on core: 0 D (569) intr_alloc: Connected src 59 to int 3 (cpu 0) D (574) cpu_start: calling init function: 0x42004248 on core: 0 I (580) sleep: Configure to isolate all GPIO pins in sleep state I (587) sleep: Enable automatic switching of GPIO sleep configuration D (594) cpu_start: calling init function: 0x42002a14 on core: 0 I (600) coexist: coex firmware version: 80b0d89 I (605) coexist: coexist rom version e7ae62f D (610) intr_alloc: Connected src 79 to int 9 (cpu 0) I (615) app_start: Starting scheduler on CPU0 D (620) intr_alloc: Connected src 57 to int 12 (cpu 0) I (620) main_task: Started on CPU0 D (624) heap_init: New heap initialised at 0x3fce9710 D (629) intr_alloc: Connected src 52 to int 13 (cpu 0) I (634) main_task: Calling app_main() I (638) stats: I (647) stats: ESP-Hosted Firmware version :: 1.0.3
I (656) stats: Transport used :: SPI only
I (664) stats: I (672) FW_MAIN: Supported features are: I (677) FW_MAIN: - WLAN over SPI I (681) FW_BT: - BT/BLE I (684) FW_BT: - HCI Over SPI I (688) FW_BT: - BLE only I (691) FW_MAIN: Capabilities: 0xe8 pp rom version: e7ae62f net80211 rom version: e7ae62f I (702) wifi:wifi driver task: 3fca7040, prio:23, stack:6656, core=0 D (707) efuse: In EFUSE_BLK1DATA1_REG is used 8 bits starting with 8 bit D (713) efuse: In EFUSE_BLK1DATA1_REG is used 8 bits starting with 0 bit D (720) efuse: In EFUSE_BLK1DATA0_REG is used 8 bits starting with 24 bit D (727) efuse: In EFUSE_BLK1DATA0_REG is used 8 bits starting with 16 bit D (734) efuse: In EFUSE_BLK1DATA0_REG is used 8 bits starting with 8 bit D (741) efuse: In EFUSE_BLK1DATA0_REG is used 8 bits starting with 0 bit I (749) wifi:wifi firmware version: fddc5e5 I (752) wifi:wifi certification version: v7.0 I (756) wifi:config NVS flash: disabled I (760) wifi:config nano formating: disabled I (764) wifi:Init data frame dynamic rx buffer num: 64 I (769) wifi:Init management frame dynamic rx buffer num: 64 I (774) wifi:Init management short buffer num: 32 I (778) wifi:Init dynamic tx buffer num: 64 I (782) wifi:Init static tx FG buffer num: 2 I (786) wifi:Init static rx buffer size: 1600 I (791) wifi:Init static rx buffer num: 16 I (794) wifi:Init dynamic rx buffer num: 64 I (799) wifi_init: rx ba win: 32 I (802) wifi_init: tcpip mbox: 32 I (806) wifi_init: udp mbox: 6 I (810) wifi_init: tcp mbox: 6 I (813) wifi_init: tcp tx win: 5744 I (818) wifi_init: tcp rx win: 5744 I (822) wifi_init: tcp mss: 1440 I (826) wifi_init: WiFi IRAM OP enabled I (830) wifi_init: WiFi RX IRAM OP enabled I (835) BLE_INIT: BT controller compile version [963cad4] I (841) phy_init: phy_version 601,98f2a71,Jun 29 2023,09:58:12 D (848) phy_init: loading PHY init data from application binary D (854) nvs: nvs_open_from_partition phy 0 D (858) nvs: nvs_get cal_version 4 D (861) nvs: nvs_get_str_or_blob cal_mac D (865) efuse: In EFUSE_BLK1DATA1_REG is used 8 bits starting with 8 bit D (872) efuse: In EFUSE_BLK1DATA1_REG is used 8 bits starting with 0 bit D (879) efuse: In EFUSE_BLK1DATA0_REG is used 8 bits starting with 24 bit D (886) efuse: In EFUSE_BLK1DATA0_REG is used 8 bits starting with 16 bit D (893) efuse: In EFUSE_BLK1DATA0_REG is used 8 bits starting with 8 bit D (900) efuse: In EFUSE_BLK1DATA0_REG is used 8 bits starting with 0 bit D (907) nvs: nvs_get_str_or_blob cal_data D (913) nvs: nvs_close 1 D (914) efuse: In EFUSE_BLK1DATA1_REG is used 8 bits starting with 8 bit D (921) efuse: In EFUSE_BLK1DATA1_REG is used 8 bits starting with 0 bit D (928) efuse: In EFUSE_BLK1DATA0_REG is used 8 bits starting with 24 bit D (935) efuse: In EFUSE_BLK1DATA0_REG is used 8 bits starting with 16 bit D (942) efuse: In EFUSE_BLK1DATA0_REG is used 8 bits starting with 8 bit D (949) efuse: In EFUSE_BLK1DATA0_REG is used 8 bits starting with 0 bit D (970) temperature_sensor: range changed, change to index 2 I (982) BLE_INIT: Bluetooth MAC: 34:85:18:96:6a:f6

I (983) FW_MAIN: ESP Bluetooth MAC addr: 34-85-18-96-6a-f6

I (983) FW_SPI: Using SPI interface I (987) gpio: GPIO[2]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 I (996) gpio: GPIO[4]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 D (1006) gdma: new group (0) at 0x3fcb6b14 D (1009) gdma: new pair (0,0) at 0x3fcb6b58 D (1014) gdma: new tx channel (0,0) at 0x3fcb6ae0 D (1018) gdma: new rx channel (0,0) at 0x3fcb6b78 D (1023) spi: SPI2 use iomux pins. D (1027) intr_alloc: Connected src 21 to int 17 (cpu 0) I (2033) FW_MAIN: Initial set up done I (2033) main_task: Returned from app_main() I (2156) FW_MAIN: INIT Interface command

D (2156) event: created task for loop 0x3fca5610 D (2156) event: created event loop 0x3fca5610 D (2159) wifi:filter: set rx policy=0 I (2162) wifi:mode : sta (34:85:18:96:6a:f4) I (2166) wifi:enable tsf D (2168) wifi:filter: set rx policy=1 D (2171) wifi:connect status 0 -> 0 D (2175) event: running task for loop 0x3fca5610 D (2179) event: running post WIFI_EVENT:2 with handler 0x4200a320 and context 0x3fca71c4 on loop 0x3fca5610 I (2189) FW_CMD: Wifi Sta mode set

I (2266) FW_MAIN: Get MAC command

sergey-suloev commented 7 months ago

[ 13.077390] esp32_spi:esp_init: esp_init: enter [ 13.082180] esp32_spi spi0.0: Probing ESP32 SPI-driver... [ 13.087688] esp32_spi spi0.0: Hardware reset [ 13.311364] esp32_spi spi0.0: ESP32 peripheral is registered to SPI bus [0], chip select [0], SPI Clock [30], SPI mode [0x02] [ 13.541040] esp32_spi spi0.0: Probe success. [ 13.545596] esp32_spi:esp_init: esp_init: ret=0 [ 14.881558] dwmac-sun8i 1c30000.ethernet eth0: Link is Up - 100Mbps/Full - flow control rx/tx [ 15.140231] esp32_spi:process_esp_bootup_event: Received ESP bootup event [ 15.147159] esp32_spi:process_event_esp_bootup: Bootup Event tag: 3 [ 15.153486] esp32_spi:esp_validate_chipset: Chipset=ESP32-S3 ID=09 detected over SPI [ 15.153498] esp32_spi:process_event_esp_bootup: Bootup Event tag: 2 [ 15.153505] esp32_spi:process_event_esp_bootup: Bootup Event tag: 0 [ 15.153510] esp32_spi:process_event_esp_bootup: Bootup Event tag: 1 [ 15.153515] esp32_spi:process_fw_data: ESP chipset's last reset cause: [ 15.153520] esp32_spi:print_reset_reason: POWERON_RESET [ 15.153525] esp32_spi:check_esp_version: ESP Firmware version: 1.0.3 [ 15.153899] esp32_spi:esp_reg_notifier: Driver init is ongoing [ 20.287113] esp32_spi:wait_and_decode_cmd_resp: Command[3] timed out [ 20.293534] esp32_spi:cmd_get_mac: wait_and_decode_cmd_resp(priv, cmd_node) failure, ret: -22 [ 20.302189] esp32_spi:esp_add_card: esp_add_network_ifaces(adapter) failure, ret: -1 [ 20.309987] esp32_spi:process_event_esp_bootup: network iterface init failed

sergey-suloev commented 7 months ago

@mantriyogesh I am using your latest code for both ESP & host with minimal changes . Here is my fork https://github.com/sergey-suloev/esp-hosted/. There were no principal changes made besides those needed to load the host driver via device tree overlay. Here is the overlay I use for orangepi-pc host:

/dts-v1/;
/plugin/;

/ {
        compatible = "allwinner,sun8i-h3";
};

&spi0 {
        #address-cells = <1>;
        #size-cells = <0>;

        esp32_spi@0 {
                compatible = "espressif,esp32-spi";
                reg = <0>;
                spi-max-frequency = <30000000>;
                handshake-gpios = <&pio 0 7 0>; /*PA7*/
                dataready-gpios = <&pio 0 8 0>; /*PA8*/
                reset-gpios = <&pio 0 9 0>;     /*PA9*/
        };
};
sergey-suloev commented 7 months ago

Here is my hardware part that I'm xperimenting on

https://drive.google.com/file/d/16apk6cmliEJHeaRr_W7zYDedQOPImX4X/view?usp=sharing

mantriyogesh commented 7 months ago

Thanks for sharing the image.

The jumper wires are too big. Can you please use shorter wires, possibly <=10cm for SPI ?

Porting guide: https://github.com/espressif/esp-hosted/blob/master/esp_hosted_ng/docs/porting_guide.md

I quick visited, there is a lot of code change in your branch.

mantriyogesh commented 7 months ago

Let me check the changes again in some time. Also, what happens if you keep smaller frequency?

This high frequency of 30M, will not work with jumper cables, of this big length.

sergey-suloev commented 7 months ago

@mantriyogesh I understand that shorter cables are better, but lower freqs didn't work at all. I tried 20M, 10M, 4M, 2M but I wasn't even able to get bootup event. For some strange reason 30M gives the best result in my case.

sergey-suloev commented 7 months ago

Thanks for sharing the image.

The jumper wires are too big. Can you please use shorter wires, possibly <=10cm for SPI ?

Porting guide: https://github.com/espressif/esp-hosted/blob/master/esp_hosted_ng/docs/porting_guide.md

I quick visited, there is a lot of code change in your branch.

It may seem a lot of changes but there are no principle changes. The problem with your master branch is that the driver isn't usable with DT. In my environment everything is loaded via DT.

mantriyogesh commented 7 months ago

As I can understand, the first transaction is fine, meaning SPI lines CLK, CS, MISO is verified. Is MOSI correctly connected to host (I suppose, PC0 place ref: https://uthings.uniud.it/control-gpio-pins-of-orange-pi-boards)

Also check the interrupts are correctly handled. Please check porting guide for some more corner cases and tuning options.

Is the SPI mode both sides mode 2? Also can try SPI mode 1?

sergey-suloev commented 7 months ago

@mantriyogesh If you look at ESP log you will see that ESP has received the "get mac" command but it didn't respond to it. So MOSI is fine too. Yes, I set mode 2 both sides. I tried SPI Mode 1 and it gives totally the same result.

sergey-suloev commented 7 months ago

[ 12.895943] esp32_spi:esp_init: esp_init: enter [ 12.900693] esp32_spi spi0.0: Probing ESP32 SPI-driver... [ 12.906293] esp32_spi spi0.0: Issue hardware reset... [ 13.141329] esp32_spi spi0.0: Done. [ 13.145083] esp32_spi spi0.0: ESP32 peripheral is registered to SPI bus [0], chip select [0], SPI Clock [30], SPI mode [0x01] [ 13.371343] esp32_spi spi0.0: Probe success. [ 13.375902] esp32_spi:esp_init: esp_init: ret=0 [ 14.586536] esp32_spi spi0.0: data ready interrupt: irq=47 [ 14.592131] esp32_spi spi0.0: handshake interrupt: irq=46 [ 14.597605] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 14.605049] esp32_spi spi0.0: SPI transfer done. [ 14.609707] esp32_spi spi0.0: process_rx_buf [ 14.614117] esp32_spi spi0.0: process_rx_buf: new packet received [ 14.620291] esp32_spi spi0.0: read packet: len=38 [ 14.625130] esp32_spi:process_esp_bootup_event: Received ESP bootup event [ 14.631999] esp32_spi:process_event_esp_bootup: Bootup Event tag: 3 [ 14.638296] esp32_spi:esp_validate_chipset: Chipset=ESP32-S3 ID=09 detected over SPI [ 14.638305] esp32_spi:process_event_esp_bootup: Bootup Event tag: 2 [ 14.638310] esp32_spi:process_event_esp_bootup: Bootup Event tag: 0 [ 14.651832] dwmac-sun8i 1c30000.ethernet eth0: Link is Up - 100Mbps/Full - flow control rx/tx [ 14.652392] esp32_spi:process_event_esp_bootup: Bootup Event tag: 1 [ 14.673486] esp32_spi:process_fw_data: ESP chipset's last reset cause: [ 14.673500] esp32_spi:print_reset_reason: POWERON_RESET [ 14.673505] esp32_spi:check_esp_version: ESP Firmware version: 1.0.3 [ 14.673839] esp32_spi:esp_reg_notifier: Driver init is ongoing [ 14.751325] esp32_spi spi0.0: write packet: len=20 [ 14.756384] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=0 [ 14.763919] esp32_spi spi0.0: SPI transfer done. [ 14.768591] esp32_spi spi0.0: data ready interrupt: irq=47 [ 14.774283] esp32_spi spi0.0: process_rx_buf [ 14.778619] esp32_spi spi0.0: process_rx_buf 252 [ 14.783407] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 14.790747] esp32_spi spi0.0: SPI transfer done. [ 14.795506] esp32_spi spi0.0: handshake interrupt: irq=46 [ 14.801033] esp32_spi spi0.0: process_rx_buf [ 14.805380] esp32_spi spi0.0: process_rx_buf 252 [ 14.810092] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 14.817417] esp32_spi spi0.0: SPI transfer done. [ 14.822163] esp32_spi spi0.0: process_rx_buf [ 14.826597] esp32_spi spi0.0: process_rx_buf: new packet received [ 14.832812] esp32_spi spi0.0: read packet: len=20 [ 14.891332] esp32_spi spi0.0: write packet: len=20 [ 14.896174] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=0 [ 14.903442] esp32_spi spi0.0: SPI transfer done. [ 14.908091] esp32_spi spi0.0: data ready interrupt: irq=47 [ 14.913636] esp32_spi spi0.0: process_rx_buf [ 14.917920] esp32_spi spi0.0: process_rx_buf 252 [ 14.922599] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 14.929782] esp32_spi spi0.0: SPI transfer done. [ 14.934468] esp32_spi spi0.0: process_rx_buf [ 14.938751] esp32_spi spi0.0: process_rx_buf 252 [ 19.841337] esp32_spi:wait_and_decode_cmd_resp: Command[3] timed out [ 19.847763] esp32_spi:cmd_get_mac: wait_and_decode_cmd_resp(priv, cmd_node) failure, ret: -22 [ 19.856354] esp32_spi:esp_add_card: esp_add_network_ifaces(adapter) failure, ret: -1 [ 19.864190] esp32_spi:process_event_esp_bootup: network iterface init failed

sergey-suloev commented 7 months ago

@mantriyogesh I added more logs to the driver (see above)

Please, compare how the following 2 commands are processed in the driver.

1) here is the first command sent

[ 14.751325] esp32_spi spi0.0: write packet: len=20 [ 14.756384] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=0 [ 14.763919] esp32_spi spi0.0: SPI transfer done. [ 14.768591] esp32_spi spi0.0: data ready interrupt: irq=47 [ 14.774283] esp32_spi spi0.0: process_rx_buf [ 14.778619] esp32_spi spi0.0: process_rx_buf 252 [ 14.783407] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 14.790747] esp32_spi spi0.0: SPI transfer done. [ 14.795506] esp32_spi spi0.0: handshake interrupt: irq=46 [ 14.801033] esp32_spi spi0.0: process_rx_buf [ 14.805380] esp32_spi spi0.0: process_rx_buf 252 [ 14.810092] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 14.817417] esp32_spi spi0.0: SPI transfer done. [ 14.822163] esp32_spi spi0.0: process_rx_buf [ 14.826597] esp32_spi spi0.0: process_rx_buf: new packet received [ 14.832812] esp32_spi spi0.0: read packet: len=20

2) and here is the second command

[ 14.891332] esp32_spi spi0.0: write packet: len=20 [ 14.896174] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=0 [ 14.903442] esp32_spi spi0.0: SPI transfer done. [ 14.908091] esp32_spi spi0.0: data ready interrupt: irq=47 [ 14.913636] esp32_spi spi0.0: process_rx_buf [ 14.917920] esp32_spi spi0.0: process_rx_buf 252 [ 14.922599] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 14.929782] esp32_spi spi0.0: SPI transfer done. [ 14.934468] esp32_spi spi0.0: process_rx_buf [ 14.938751] esp32_spi spi0.0: process_rx_buf 252 [ 19.841337] esp32_spi:wait_and_decode_cmd_resp: Command[3] timed out

It's obvious that the timeout happens because ESP doesn't issue a handshake interrupt event in time. This may happen if ESP hangs on processing "get mac" command.

FYI: "process_rx_buf 252" means we exit from process_rx_buf due to the condition:

    if (header->if_type >= ESP_MAX_IF) {
            dev_dbg(&spi_ctx->spi->dev, "%s %u\n", __func__, __LINE__);
            return -EINVAL;
    }
sergey-suloev commented 7 months ago

The following log happens when I set a SPI freq < 30M:

[ 12.819285] esp32_spi:esp_init: esp_init: enter [ 12.824103] esp32_spi spi0.0: Probing ESP32 SPI-driver... [ 12.829593] esp32_spi spi0.0: Issue hardware reset... [ 13.051357] esp32_spi spi0.0: Done. [ 13.055184] esp32_spi spi0.0: ESP32 peripheral is registered to SPI bus [0], chip select [0], SPI Clock [80], SPI mode [0x01] [ 13.281308] esp32_spi spi0.0: Probe success. [ 13.285864] esp32_spi:esp_init: esp_init: ret=0 [ 14.502511] esp32_spi spi0.0: data ready interrupt: irq=47 [ 14.508063] esp32_spi spi0.0: handshake interrupt: irq=46 [ 14.513674] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 14.520753] esp32_spi spi0.0: SPI transfer done. [ 14.525442] esp32_spi spi0.0: process_rx_buf [ 14.529726] esp32_spi spi0.0: process_rx_buf 260

FYI: "process_rx_buf 260" means we exit from process_rx_buf due to the condition:

    /* Validate received SKB. Check len and offset fields */
    if (offset != sizeof(struct esp_payload_header)) {
            dev_dbg(&spi_ctx->spi->dev, "%s %u\n", __func__, __LINE__);
            return -EINVAL;
    }
mantriyogesh commented 7 months ago

https://github.com/espressif/esp-hosted/issues/333#issuecomment-1944275703

Sorry I didn't mean mosi, I wanted to refer to miso in fact.

https://github.com/espressif/esp-hosted/issues/333#issuecomment-1944447631

Something looks wrong in setting the smaller freq. From log,

[ 13.055184] esp32_spi spi0.0: ESP32 peripheral is registered to SPI bus [0], chip select [0], SPI Clock [80], SPI mode [0x01]

It appears that current frequency been set is 80MHz.

sergey-suloev commented 7 months ago

Yes, you are right. A mistype in that freq value. Here is the correct log for 10M. It is actually the same as the one for 30M.

[ 12.490743] esp32_spi:esp_init: esp_init: enter [ 12.495654] esp32_spi spi0.0: Probing ESP32 SPI-driver... [ 12.501180] esp32_spi spi0.0: Issue hardware reset... [ 12.721556] esp32_spi spi0.0: Done. [ 12.726270] esp32_spi spi0.0: ESP32 peripheral is registered to SPI bus [0], chip select [0], SPI Clock [10], SPI mode [0x01] [ 12.961522] esp32_spi spi0.0: Probe success. [ 12.966070] esp32_spi:esp_init: esp_init: ret=0 [ 14.174986] esp32_spi spi0.0: data ready interrupt: irq=47 [ 14.180553] esp32_spi spi0.0: handshake interrupt: irq=46 [ 14.186056] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 14.195145] esp32_spi spi0.0: SPI transfer done. [ 14.199824] esp32_spi spi0.0: process_rx_buf [ 14.204198] esp32_spi spi0.0: process_rx_buf: new packet received [ 14.210340] esp32_spi spi0.0: read packet: len=38 [ 14.215156] esp32_spi:process_esp_bootup_event: Received ESP bootup event [ 14.222035] esp32_spi:process_event_esp_bootup: Bootup Event tag: 3 [ 14.228356] esp32_spi:esp_validate_chipset: Chipset=ESP32-S3 ID=09 detected over SPI [ 14.236172] esp32_spi:process_event_esp_bootup: Bootup Event tag: 2 [ 14.242482] esp32_spi:process_event_esp_bootup: Bootup Event tag: 0 [ 14.248763] esp32_spi:process_event_esp_bootup: Bootup Event tag: 1 [ 14.255056] esp32_spi:process_fw_data: ESP chipset's last reset cause: [ 14.261612] esp32_spi:print_reset_reason: POWERON_RESET [ 14.266856] esp32_spi:check_esp_version: ESP Firmware version: 1.0.3 [ 14.273622] esp32_spi:esp_reg_notifier: Driver init is ongoing [ 14.331860] esp32_spi spi0.0: write packet: len=20 [ 14.339453] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=0 [ 14.349411] esp32_spi spi0.0: SPI transfer done. [ 14.354149] esp32_spi spi0.0: data ready interrupt: irq=47 [ 14.359721] esp32_spi spi0.0: process_rx_buf [ 14.364063] esp32_spi spi0.0: process_rx_buf 252 [ 14.368715] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 14.377715] esp32_spi spi0.0: SPI transfer done. [ 14.382429] esp32_spi spi0.0: handshake interrupt: irq=46 [ 14.387905] esp32_spi spi0.0: process_rx_buf [ 14.387919] esp32_spi spi0.0: process_rx_buf 252 [ 14.396938] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 14.407357] esp32_spi spi0.0: SPI transfer done. [ 14.412127] esp32_spi spi0.0: process_rx_buf [ 14.416433] esp32_spi spi0.0: process_rx_buf: new packet received [ 14.422650] esp32_spi spi0.0: read packet: len=20 [ 14.481520] esp32_spi spi0.0: write packet: len=20 [ 14.486363] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=0 [ 14.495335] esp32_spi spi0.0: SPI transfer done. [ 14.499990] esp32_spi spi0.0: data ready interrupt: irq=47 [ 14.505528] esp32_spi spi0.0: process_rx_buf [ 14.509823] esp32_spi spi0.0: process_rx_buf 252 [ 14.514492] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 14.523389] esp32_spi spi0.0: SPI transfer done. [ 14.528027] esp32_spi spi0.0: process_rx_buf [ 14.532329] esp32_spi spi0.0: process_rx_buf 252 [ 19.441512] esp32_spi:wait_and_decode_cmd_resp: Command[3] timed out [ 19.447917] esp32_spi:cmd_get_mac: wait_and_decode_cmd_resp(priv, cmd_node) failure, ret: -22 [ 19.456498] esp32_spi:esp_add_card: esp_add_network_ifaces(adapter) failure, ret: -1 [ 19.464270] esp32_spi:process_event_esp_bootup: network iterface init failed

sergey-suloev commented 7 months ago

I think ESP side must have more extensive logging

mantriyogesh commented 7 months ago

I can send you to enable the logging, specially at the transport level (both ESP and host), but the most imp thing is to trim the wire length.

Also do you happen to have logic analyzer at your side?

sergey-suloev commented 7 months ago

@mantriyogesh Ive already changed wires to 9cm, there is no change in behavior. Also, behavior is consistent on any freq I tried : 1M, 2M, 4M, 8M, 10M, 20M, 30M. I think wire length doesn't matter too much of lower freqs. Everything looks like ESP hangs on processing GetMAC command.

mantriyogesh commented 7 months ago

Do you use

  1. correct input power rated adapter? Insufficient power can lead to incorrect peripheral behaviour.
  2. is your Linux allowed to power save? if so, can you please disable it?

As I understand, the SPI is unreliably working, with some messages reaching and some not, which could be classic issue of interoperability of spi timing. but to confirm, logic analyzer dump can be useful.

Let me provide some debug logs to introduce in both esp and host.

sergey-suloev commented 7 months ago

Here is a part of my linux config 

#
# CPU Power Management
#

#
# CPU Frequency scaling
#
CONFIG_CPU_FREQ=y
CONFIG_CPU_FREQ_GOV_ATTR_SET=y
CONFIG_CPU_FREQ_GOV_COMMON=y
CONFIG_CPU_FREQ_STAT=y
CONFIG_CPU_FREQ_DEFAULT_GOV_PERFORMANCE=y
# CONFIG_CPU_FREQ_DEFAULT_GOV_POWERSAVE is not set
# CONFIG_CPU_FREQ_DEFAULT_GOV_USERSPACE is not set
# CONFIG_CPU_FREQ_DEFAULT_GOV_ONDEMAND is not set
# CONFIG_CPU_FREQ_DEFAULT_GOV_CONSERVATIVE is not set
# CONFIG_CPU_FREQ_DEFAULT_GOV_SCHEDUTIL is not set
CONFIG_CPU_FREQ_GOV_PERFORMANCE=y
CONFIG_CPU_FREQ_GOV_POWERSAVE=m
CONFIG_CPU_FREQ_GOV_USERSPACE=m
CONFIG_CPU_FREQ_GOV_ONDEMAND=y
CONFIG_CPU_FREQ_GOV_CONSERVATIVE=m
CONFIG_CPU_FREQ_GOV_SCHEDUTIL=y

#
# CPU frequency scaling drivers
#
CONFIG_CPUFREQ_DT=y
CONFIG_CPUFREQ_DT_PLATDEV=y
# CONFIG_ARM_ALLWINNER_SUN50I_CPUFREQ_NVMEM is not set
# end of CPU Frequency scaling

#
# CPU Idle
#
# CONFIG_CPU_IDLE is not set
# end of CPU Idle
# end of CPU Power Management
sergey-suloev commented 7 months ago

Do you use

  1. correct input power rated adapter? Insufficient power can lead to incorrect peripheral behaviour. 1) power is fine

  2. is your Linux allowed to power save? if so, can you please disable it?

2) see post above

As I understand, the SPI is unreliably working, with some messages reaching and some not, which could be classic issue of interoperability of spi timing. but to confirm, logic analyzer dump can be useful.

Let me provide some debug logs to introduce in both esp and host.

Why do you think so ? Look at this post again https://github.com/espressif/esp-hosted/issues/333#issuecomment-1944431087. Do you see that a handshake interrupt didn't happen ? ESP is responsible for this interrupt. Also, look at the final row for this log https://github.com/espressif/esp-hosted/issues/333#issuecomment-1941107937. ESP received the GetMAC command! Now it was ESP's turn to continue communication but it didn't want to do it.

mantriyogesh commented 7 months ago

base: 4f75cfcaf22831c9ebd0800bb30cb3a62d7ba6d2 0001-Debug-logs-uncompiled-added.patch

mantriyogesh commented 7 months ago

I thought, 

[ 14.592131] esp32_spi spi0.0: handshake interrupt: irq=46

is handshake interrupt?

mantriyogesh commented 7 months ago

above debug patch is uncompiled one, so you might have to fix and build, if any build issue. base is your branch commit latest.

esp and host both has changes. basically, whatever at transport (rx/tx) is expected to print.

the esp is sending the msg, but it is not understood by the host, due to spi timings. most likely this will confirm, that the spi incoming message at host is bit shifted, but to confirm nicely, you would need logic analyzer.

If the logs have shown the output is bit shifted, you might have to resolve your porting for spi timings. check porting guide again, as these are scenarios already covered there.

We work with different kind of hosts and these interop spi timing issues are common. Once you fix, it will always work.

sergey-suloev commented 7 months ago

I thought,

[ 14.592131] esp32_spi spi0.0: handshake interrupt: irq=46

is handshake interrupt?

Yes, it is an interrupt, meaning that ESP must rise the GPIO in time but it didn't. As a result of not rising GPIO the host timeout happens

mantriyogesh commented 7 months ago

if you get into 

if (offset != sizeof(struct esp_payload_header)) {
            dev_dbg(&spi_ctx->spi->dev, "%s %u\n", __func__, __LINE__);
            return -EINVAL;
    }

Anyway, it means that your timings are not correct.

What is offset received? it will 1 (or 2?) bit left or right shifted. anyway, logic analyzer?

sergey-suloev commented 7 months ago

if you get into

if (offset != sizeof(struct esp_payload_header)) {
            dev_dbg(&spi_ctx->spi->dev, "%s %u\n", __func__, __LINE__);
            return -EINVAL;
    }

Anyway, it means that your timings are not correct.

What is offset received? it will 1 (or 2?) bit left or right shifted. anyway, logic analyzer?

Offset isn't a problem anymore, it happened only at 80MHz (I set this freq by mistake) See the latest log which happens at all freqs <= 30MHz https://github.com/espressif/esp-hosted/issues/333#issuecomment-1945499111

log records "process_rx_buf 252" mean that we exit from process_rx_buf due to the condition:

if (header->if_type >= ESP_MAX_IF) {
        dev_dbg(&spi_ctx->spi->dev, "%s %u\n", __func__, __LINE__);
        return -EINVAL;
}
mantriyogesh commented 7 months ago

Have you tried https://github.com/espressif/esp-hosted/issues/333#issuecomment-1945701242?

sergey-suloev commented 7 months ago

here is my capture with logic analyzer at SPI freq 1MHz https://drive.google.com/file/d/15lUXWEUGnysNATkUVzJV2dF2Z0ZOUQek/view?usp=sharing

@mantriyogesh according to what I see from the capture , communication stops at the 2nd message because SPI master does not set CS line to 0. It seems like my host looses handshakes. I think this is because ESP keeps handshake line high all the time. When ESP needs to send raising edge it set the line to 0 and then immediately to 1. This transition is too short.

Screenshot from 2024-02-17 18-07-55

On the picture you can see bootup event, the first master message and second master message, which is "timed out". During processing the second message the host does not receive handshake interrupt.

Compare the logs: the first message

[ 15.011542] esp32_spi spi0.0: write packet: len=20 [ 15.016495] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=0 [ 15.036366] esp32_spi spi0.0: SPI transfer done. [ 15.041042] esp32_spi spi0.0: data ready interrupt: irq=47 [ 15.046615] esp32_spi spi0.0: process_rx_buf [ 15.050903] esp32_spi spi0.0: process_rx_buf: header->if_type(15) >= ESP_MAX_IF(5) [ 15.058590] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 15.078321] esp32_spi spi0.0: SPI transfer done. [ 15.083023] esp32_spi spi0.0: handshake interrupt: irq=46 [ 15.088453] esp32_spi spi0.0: process_rx_buf [ 15.092774] esp32_spi spi0.0: process_rx_buf: header->if_type(15) >= ESP_MAX_IF(5) [ 15.100567] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 15.120215] esp32_spi spi0.0: SPI transfer done. [ 15.124890] esp32_spi spi0.0: process_rx_buf [ 15.137695] esp32_spi spi0.0: process_rx_buf: new packet received [ 15.143979] esp32_spi spi0.0: read packet: len=20

the second message

[ 15.124890] esp32_spi spi0.0: process_rx_buf [ 15.137695] esp32_spi spi0.0: process_rx_buf: new packet received [ 15.143979] esp32_spi spi0.0: read packet: len=20 [ 15.194030] esp32_spi spi0.0: write packet: len=20 [ 15.198894] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=0 [ 15.218652] esp32_spi spi0.0: SPI transfer done. [ 15.223351] esp32_spi spi0.0: data ready interrupt: irq=47 [ 15.228962] esp32_spi spi0.0: process_rx_buf [ 15.233313] esp32_spi spi0.0: process_rx_buf: header->if_type(15) >= ESP_MAX_IF(5) [ 15.241896] esp32_spi spi0.0: work handler: trans_ready=1, rx_pending=1 [ 15.261602] esp32_spi spi0.0: SPI transfer done. [ 15.266292] esp32_spi spi0.0: process_rx_buf [ 15.266306] esp32_spi spi0.0: process_rx_buf: header->if_type(15) >= ESP_MAX_IF(5) [ 20.161359] esp32_spi:wait_and_decode_cmd_resp: Command[3] timed out [ 20.167767] esp32_spi:cmd_get_mac: wait_and_decode_cmd_resp(priv, cmd_node) failure, ret: -22 [ 20.176347] esp32_spi:esp_add_card: esp_add_network_ifaces(adapter) failure, ret: -1 [ 20.184184] esp32_spi:process_event_esp_bootup: network iterface init failed

mantriyogesh commented 7 months ago

Please check https://github.com/espressif/esp-hosted/blob/master/esp_hosted_fg/esp/esp_driver/network_adapter/main/spi_slave_api.c#L545

Logic. Alternatively, plz try FG once with correct freq.

sergey-suloev commented 7 months ago

Please check https://github.com/espressif/esp-hosted/blob/master/esp_hosted_fg/esp/esp_driver/network_adapter/main/spi_slave_api.c#L545

Logic. Alternatively, plz try FG once with correct freq.

do you mean I can try FG firmware with NG host driver ??

mantriyogesh commented 7 months ago

Sorry if I confused you. Either flavor can only work with its own firmware and it's own host driver, that to on same for commit.

If you want to stick with NG, just check the hs disable logic and try in NG..

sergey-suloev commented 7 months ago

@mantriyogesh I added "hs disable" to NG and it worked. Thanks a lot!

https://github.com/sergey-suloev/esp-hosted/commit/e51d5a0e41878c26a51c01b91dc73734d952c1b6

mantriyogesh commented 7 months ago

Btw, you may optionally optimise your freq of operation, by increasing spi clock in 1M steps. Higher the freq, better the performance. You could reach till 40m, by the time your setup respects interoperability and spi timings. Proper PCB will be much robust than jumper cables setup.

sergey-suloev commented 7 months ago

Btw, you may optionally optimise your freq of operation, by increasing spi clock in 1M steps. Higher the freq, better the performance. You could reach till 40m, by the time your setup respects interoperability and spi timings. Proper PCB will be much robust than jumper cables setup.

Ok, I will try increase the freq later. At the moment it's 100% stable at 30M and any lower freq too.