Ethernet SPI W5500 error handling

[UmiKod]

I am working with W5500 external Ethernet module and ESP32-wroom-32 and ESP-IDF v4.4. In my design, the W5500 module should be on another board that connects via a connector to the main esp32 board. Because of this, I want to handle errors from the module.

When all is connected, everything works ok. But when I pull out the module during operation, no ETH_EVENT occur, and in the terminal there are endless errors from "spi_master" and "w5500.mac". I did not find any event handlers from the spi master.
The question is how do I know in the program that the w5500 has an error and is disabled or damaged?
Error listing:

• D (85554) spi_master: Allocate RX buffer for DMA
  E (87094) spi_master: check_trans_valid(689): txdata transfer > host maximum
  E (87094) w5500.mac: w5500_read(97): spi transmit failed
  E (87094) w5500.mac: w5500_read_buffer(188): read RX buffer failed
  E (87094) w5500.mac: emac_w5500_receive(572): read payload failed, len=65533, offset=1
  E (88104) spi_master: check_trans_valid(689): txdata transfer > host maximum
  E (88104) w5500.mac: w5500_read(97): spi transmit failed
  E (88104) w5500.mac: w5500_read_buffer(188): read RX buffer failed
  E (88104) w5500.mac: emac_w5500_receive(572): read payload failed, len=65533, offset=1

[ESP_ondrej]

There is no such check since disconnecting SPI device on the go is quite non-standard operation. However, if your design requires such thing for some reason, you can implement periodic check as discussed here - viewtopic.php?f=13&t=27456

BTW: when you disconnect the W5500, are you able to send or receive any data? Does socket operation returns error?

[UmiKod]

There is no such check since disconnecting SPI device on the go is quite non-standard operation.

When starting, even without the module, it says that everything is fine and sends events about the start. And then there are no errors. And since there was no GOT_IP event, it was all good. There will be no mistakes. Isn't this a standard situation at startup to check if the module is present?
Why does the w5500.mac task print errors to the terminal that it cannot send, but it cannot generate an error event?

• E (257464) w5500.mac: emac_w5500_transmit(523): free size (350) < send length (0).

However, if your design requires such thing for some reason, you can implement periodic check as discussed here

Thank you ESP_ondrej. The provided topic helped me with the status check.
when val = 0 - the module is missing.
when val = 250 - the module is pushed, but no network cable is connected.
when val = 255 - there is a connection and everything works.

But I don't understand how to restart w5500.
In my code, I execute:

Code: [Select all] [Expand/Collapse]

1. esp_eth_stop(s_eth_handle);
2. vTaskDelay(10);
3. esp_eth_start(s_eth_handle);

GeSHi © Codebox Plus Extension

but it doesn't help in initializing the module.
After reconnecting, it cyclically sends:

• I (304494) WM: W5500_REG_PHYCFGR val = 250
  I (305494) WM_eth: Retry Timer Tick!
  I (305494) WM: W5500_REG_PHYCFGR val = 250
  I (306494) WM_eth: Retry Timer Tick!
  I (306494) WM: W5500_REG_PHYCFGR val = 255
  D (306504) w5500.mac: working in 100Mbps
  D (306504) w5500.mac: working in full duplex
  D (306504) w5500.mac: link is upI (306614) WM_eth: Link Up
  I (307494) WM_eth: Retry Timer Tick!
  I (307494) WM: W5500_REG_PHYCFGR val = 250
  I (308494) WM_eth: Retry Timer Tick!
  I (308494) WM: W5500_REG_PHYCFGR val = 255
  I (309494) WM_eth: Retry Timer Tick!
  I (309494) WM: W5500_REG_PHYCFGR val = 250
  I (310494) WM_eth: Retry Timer Tick!
  I (310494) WM: W5500_REG_PHYCFGR val = 250
  D (310504) w5500.mac: link is down
  I (310584) WM_eth: Link Down
  I (311494) WM_eth: Retry Timer Tick!
  I (311494) WM: W5500_REG_PHYCFGR val = 255
  I (312494) WM_eth: Retry Timer Tick!
  I (312494) WM: W5500_REG_PHYCFGR val = 250
  I (313494) WM_eth: Retry Timer Tick!
  I (313494) WM: W5500_REG_PHYCFGR val = 255
  I (314494) WM_eth: Retry Timer Tick!
  I (314494) WM: W5500_REG_PHYCFGR val = 250
  I (315494) WM_eth: Retry Timer Tick!

What else needs to be restarted to re-initialize the w5500 module successfully?

BTW: when you disconnect the W5500, are you able to send or receive any data? Does socket operation returns error?

I use esp_http_client. So I start sending the data and I can do it, but then after I get HTTP_EVENT_ERROR and HTTP_EVENT_DISCONNECTED. But I also get the same errors when there is no internet connection.

[ESP_ondrej]

Why does the w5500.mac task print errors to the terminal that it cannot send, but it cannot generate an error event?
E (257464) w5500.mac: emac_w5500_transmit(523): free size (350) < send length (0).

What version of IDF do you use? Could you please try master branch or v5.0 RC? Socket `sendto` should return an error on this condition.

[UmiKod]

What version of IDF do you use?

I am working with W5500 external Ethernet module and ESP32-wroom-32 and ESP-IDF v4.4.

Could you please try master branch or v5.0 RC? Socket `sendto` should return an error on this condition.

I tried v5.0 rc.
but this version works just as bad, even worse. Microcontroller often "panics".There were problem that did not exist in the previous version.
Here is a printout of the terminal in various situations:
1.At the beginning of work. If the w5500 module is not connected. Often, but not every time, it "panics".

Code: Select all

D (905) intr_alloc: Connected src 22 to int 3 (cpu 1)
D (915) spi: SPI2 use gpio matrix.
D (915) intr_alloc: Connected src 30 to int 4 (cpu 1)
D (925) spi_hal: eff: 10000, limit: 26666k(/2), 0 dummy, -1 delay
D (925) spi_master: SPI2: New device added to CS0, effective clock: 10000kHz
I (935) w5500.mac: version=0
E (935) spi_master: check_trans_valid(692): txdata transfer > host maximum
E (945) w5500.mac: w5500_read(89): spi transmit failed
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.

Core  1 register dump:
PC      : 0x4008b5f7  PS      : 0x00060033  A0      : 0x80088bc4  A1      : 0x3ffb94e0
0x4008b5f7: spinlock_acquire at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_hw_support/include/spinlock.h:89
 (inlined by) xPortEnterCriticalTimeout at F:/Espressif/frameworks/esp-idf-v5.0/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:308

A2      : 0x0006006f  A3      : 0xffffffff  A4      : 0x00060023  A5      : 0x00060023
A6      : 0x3ffb93f0  A7      : 0x0000abab  A8      : 0x8008aa8f  A9      : 0x3ffb94e0
A10     : 0x3ffb3764  A11     : 0x3ffb3764  A12     : 0x00000004  A13     : 0x00060023
A14     : 0x00000002  A15     : 0x0000abab  SAR     : 0x00000004  EXCCAUSE: 0x0000001c
EXCVADDR: 0x0006006f  LBEG    : 0x400014fd  LEND    : 0x4000150d  LCOUNT  : 0xfffffffd

Backtrace: 0x4008b5f4:0x3ffb94e0 0x40088bc1:0x3ffb9510 0x40088f77:0x3ffb9540 0x400e0a46:0x3ffb9580 0x400e0abf:0x3ffb95a0 0x400e0b01:0x3ffb9600 0x400e168d:0x3ffb9630 0x400e0cbd:0x3ffb9670
0x4008b5f4: xt_utils_get_raw_core_id at F:/Espressif/frameworks/esp-idf-v5.0/components/xtensa/include/xt_utils.h:51
 (inlined by) spinlock_acquire at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_hw_support/include/spinlock.h:78
 (inlined by) xPortEnterCriticalTimeout at F:/Espressif/frameworks/esp-idf-v5.0/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:308
0x40088bc1: vPortEnterCritical at F:/Espressif/frameworks/esp-idf-v5.0/components/freertos/FreeRTOS-Kernel/portable/xtensa/include/freertos/portmacro.h:573
 (inlined by) prvNotifyQueueSetContainer at F:/Espressif/frameworks/esp-idf-v5.0/components/freertos/FreeRTOS-Kernel/queue.c:3106
0x40088f77: xQueueGenericSend at F:/Espressif/frameworks/esp-idf-v5.0/components/freertos/FreeRTOS-Kernel/queue.c:872
0x400e0a46: w5500_unlock at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_eth/src/esp_eth_mac_w5500.c:51
0x400e0abf: w5500_read at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_eth/src/esp_eth_mac_w5500.c:92
0x400e0b01: w5500_read_buffer at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_eth/src/esp_eth_mac_w5500.c:180
0x400e168d: emac_w5500_receive at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_eth/src/esp_eth_mac_w5500.c:564 (discriminator 2)
0x400e0cbd: emac_w5500_task at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_eth/src/esp_eth_mac_w5500.c:331

2. I am attaching an additional file "terminal.txt" of the terminal output of interesting events when I disconnect the module during an HTTPS request, how ESP32 behaves. It "panics" and reboots, after which it successfully initializes without the module.

3. There is some progress after reloading the module. It was possible to initialize it so that it does not reboot cyclically. When val > 0, the code is executed:

Code: [Select all] [Expand/Collapse]

1. s_phy->reset_hw(s_phy);
2. vTaskDelay(10);
3. s_mac->init(s_mac);
4. s_phy->init(s_phy);
5. esp_netif_dhcpc_start(eth_netif);
6. error = esp_eth_start(s_eth_handle);

GeSHi © Codebox Plus Extension

but something prevents it from getting a new IP address. Although DHCPC starts. Therefore, there is still no Internet after switching the module.Here is the listing for this:

Code: Select all

I (57795) WM: W5500_REG_PHYCFGR val = 0
I (58795) WM_eth: Retry Timer Tick!
I (58795) WM: W5500_REG_PHYCFGR val = 250
I (59795) WM_eth: Retry Timer Tick!
I (59795) WM: W5500_REG_PHYCFGR val = 255
I (59895) w5500.mac: version=4
D (59905) esp_netif_lwip: check: remote, if=0x3ffbfd98 fn=0x400dde78
0x400dde78: esp_netif_dhcpc_start_api at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_netif/lwip/esp_netif_lwip.c:1251

D (59905) esp_netif_lwip: esp_netif_dhcpc_start_api esp_netif:0x3ffbfd98
D (59905) esp_netif_lwip: dhcp client re init
D (59905) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (59925) event: running post ETH_EVENT:0 with handler 0x400e068c and context 0x3ffbff2c on loop 0x3ffbcbec
0x400e068c: eth_action_start at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_eth/src/esp_eth_netif_glue.c:76

D (59925) esp_eth.netif.netif_glue: eth_action_start: 0x3ffbfed4, 0x3f41d54c, 0, 0x3ffc12ac, 0x3ffb98cc
D (59935) esp_netif_handlers: esp_netif action has started with netif0x3ffbfd98 from event_id=0
D (59945) esp_netif_lwip: check: remote, if=0x3ffbfd98 fn=0x400dd970
0x400dd970: esp_netif_start_api at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_netif/lwip/esp_netif_lwip.c:906


D (59945) esp_netif_lwip: esp_netif_start_api 0x3ffbfd98
D (59955) esp_netif_lwip: esp_netif_get_hostname esp_netif:0x3ffbfd98
D (59955) esp_netif_lwip: check: local, if=0x3ffbfd98 fn=0x400de410
0x400de410: esp_netif_update_default_netif_lwip at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_netif/lwip/esp_netif_lwip.c:272


D (59965) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffbfd98
D (59975) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (59975) event: running post ETH_EVENT:0 with handler 0x400d735c and context 0x3ffc0034 on loop 0x3ffbcbec
0x400d735c: eth_event_handler at F:/ESP_Projects/VSCode/webserver/main/work_mode.c:931

I (59985) WM_eth: Started
I (60935) WM_eth: Retry Timer Tick!
I (60935) WM: W5500_REG_PHYCFGR val = 250
I (61935) WM_eth: Retry Timer Tick!
I (61935) WM: W5500_REG_PHYCFGR val = 250
I (62935) WM_eth: Retry Timer Tick!
I (62935) WM: W5500_REG_PHYCFGR val = 255
D (63935) w5500.mac: working in 100Mbps
D (63935) w5500.mac: working in full duplex
D (63935) w5500.mac: link is up
D (63935) event: running post ETH_EVENT:2 with handler 0x400e061c and context 0x3ffbff8c on loop 0x3ffbcbec
0x400e061c: eth_action_connected at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_eth/src/esp_eth_netif_glue.c:99

D (63945) esp_eth.netif.netif_glue: eth_action_connected: 0x3ffbfed4, 0x3f41d54c, 2, 0x3ffc12ac, 0x3ffb98cc
D (63955) esp_netif_handlers: esp_netif action connected with netif0x3ffbfd98 from event_id=2
D (63955) esp_netif_lwip: check: remote, if=0x3ffbfd98 fn=0x400ddbbc
0x400ddbbc: esp_netif_up_api at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_netif/lwip/esp_netif_lwip.c:1458


D (63965) esp_netif_lwip: esp_netif_up_api esp_netif:0x3ffbfd98
I (63965) WM_eth: Retry Timer Tick!
D (63975) esp_netif_lwip: check: local, if=0x3ffbfd98 fn=0x400de410
0x400de410: esp_netif_update_default_netif_lwip at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_netif/lwip/esp_netif_lwip.c:272


D (63985) esp_netif_lwip: esp_netif_update_default_netif_lwip 0x3ffbfd98
D (63985) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (63995) esp_netif_lwip: check: remote, if=0x3ffbfd98 fn=0x400dde78
0x400dde78: esp_netif_dhcpc_start_api at F:/Espressif/frameworks/esp-idf-v5.0/components/esp_netif/lwip/esp_netif_lwip.c:1251


D (64005) esp_netif_lwip: esp_netif_dhcpc_start_api esp_netif:0x3ffbfd98
I (64005) WM: W5500_REG_PHYCFGR val = 255
D (64005) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffbfd98
D (64015) esp_netif_lwip: if0x3ffbfd98 start ip lost tmr: already started
D (64025) esp_netif_lwip: starting dhcp client
D (64035) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (64035) event: running post ETH_EVENT:2 with handler 0x400d735c and context 0x3ffc0034 on loop 0x3ffbcbec
0x400d735c: eth_event_handler at F:/ESP_Projects/VSCode/webserver/main/work_mode.c:931

I (64045) WM_eth: Link Up
I (65015) WM_eth: Retry Timer Tick!
I (65015) WM: W5500_REG_PHYCFGR val = 255
I (66015) WM_eth: Retry Timer Tick!
I (66015) WM: W5500_REG_PHYCFGR val = 255
I (67015) WM_eth: Retry Timer Tick!
I (67015) WM: W5500_REG_PHYCFGR val = 255
I (68015) WM_eth: Retry Timer Tick!
I (68015) WM: W5500_REG_PHYCFGR val = 255
I (69015) WM_eth: Retry Timer Tick!
I (69015) WM: W5500_REG_PHYCFGR val = 255

[ESP_ondrej]

Unfortunately, I am quite busy with other tasks and your use case is a bit non-standard. Therefore I have to give it lower priority. I'll try to have a look at it later. I hope you understand it.

but something prevents it from getting a new IP address

It could be caused by a fact that the ESP-NETIF is not aware of the change since there was no proper link down or Ethernet stop event. Try to stop and start the Ethernet driver.

[asdaaa]

Why does the w5500.mac task print errors to the terminal that it cannot send, but it cannot generate an error event?
E (257464) w5500.mac: emac_w5500_transmit(523): free size (350) < send length (0).

What version of IDF do you use? Could you please try master branch or v5.0 RC? Socket `sendto` should return an error on this condition.

How do you solve“ E (257464) w5500. mac: emac_ W5500_ Transit (523): free size (350)<send length (0). ”This problem

[MikeMyhre]

Why does the w5500.mac task print errors to the terminal that it cannot send, but it cannot generate an error event?
E (257464) w5500.mac: emac_w5500_transmit(523): free size (350) < send length (0).

What version of IDF do you use? Could you please try master branch or v5.0 RC? Socket `sendto` should return an error on this condition.

How do you solve“ E (257464) w5500. mac: emac_ W5500_ Transit (523): free size (350)<send length (0). ”This problem

The driver code in esp_eth_mac_w5500.c has the length and free values reversed in the message. In the error message quoted above, the length is 350, the space is 0.
I had this error on one board out of 6 prototypes. It turned out it was a short between two of the SPI lines (solder bridge on the pins).
I think the link is established by the chip itself and if the first thing the SPI needs to do is get a DHCP address. When the ESP32 TCP stack tries to send the DHCP packet, it finds out there is not transmit space available if SPI is not working correctly.