esp-idf: ENC28J60 last transmit still in progress error (IDFGH-2673)

Environment

  • Development Kit: ESP32-Wrover-Kit
  • Kit version (for WroverKit/PicoKit/DevKitC): v4.1
  • Module or chip used: ESP32-D0WD
  • IDF version: v4.1-dev-2222-g7647b5c66
  • Build System: CMake
  • Compiler version: xtensa-esp32-elf-gcc (crosstool-NG esp-2019r2) 8.2.0
  • Operating System: Linux
  • Power Supply: USB|external 5V&Battery

Problem Description

In some recent commits finally got ENC28J60 support and during first tests periodically got the following error:

E (1740376) enc28j60: emac_enc28j60_transmit(766): last transmit still in progress

Expected Behavior

No errors

Actual Behavior

Errors periodically appears

Steps to reproduce

  1. make esp32 IP and MAC statically binded
  2. run ‘ping <ESP32_IP> -s 1400’
  3. build/flash/monitor enc28j60 example
  4. continue monitor
  5. reboot esp32 or unplug/plag RJ45 connector or simply wait > 10 minutes

Code to reproduce this issue

https://github.com/espressif/esp-idf/tree/master/examples/ethernet/enc28j60

Debug Logs

I (28) boot: ESP-IDF v4.1-dev-2222-g7647b5c66 2nd stage bootloader
I (28) boot: compile time 15:49:45
I (29) boot: chip revision: 1
I (41) boot.esp32: SPI Speed      : 40MHz
I (41) boot.esp32: SPI Mode       : DIO
I (42) boot.esp32: SPI Flash Size : 2MB
I (46) boot: Enabling RNG early entropy source...
I (52) boot: Partition Table:
I (55) boot: ## Label            Usage          Type ST Offset   Length
I (63) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (70) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (78) boot:  2 factory          factory app      00 00 00010000 00100000
I (85) boot: End of partition table
I (89) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x10830 ( 67632) map
I (123) esp_image: segment 1: paddr=0x00020858 vaddr=0x3ffb0000 size=0x021d0 (  8656) load
I (127) esp_image: segment 2: paddr=0x00022a30 vaddr=0x40080000 size=0x00404 (  1028) load
0x40080000: _WindowOverflow4 at /home/user/esp/esp-mdf/esp-idf/components/freertos/xtensa/xtensa_vectors.S:1789

I (130) esp_image: segment 3: paddr=0x00022e3c vaddr=0x40080404 size=0x0b2e4 ( 45796) load
I (158) esp_image: segment 4: paddr=0x0002e128 vaddr=0x00000000 size=0x01ef0 (  7920) 
I (161) esp_image: segment 5: paddr=0x00030020 vaddr=0x400d0020 size=0x30fb4 (200628) map
0x400d0020: _stext at ??:?

I (244) boot: Loaded app from partition at offset 0x10000
I (244) boot: Disabling RNG early entropy source...
I (244) cpu_start: Pro cpu up.
I (248) cpu_start: Application information:
I (253) cpu_start: Project name:     enc28j60
I (258) cpu_start: App version:      1
I (262) cpu_start: Compile time:     Feb 11 2020 16:04:13
I (268) cpu_start: ELF file SHA256:  8ff1afa2d0b1bef1...
I (274) cpu_start: ESP-IDF:          v4.1-dev-2222-g7647b5c66
I (281) cpu_start: Starting app cpu, entry point is 0x400812f8
0x400812f8: call_start_cpu1 at /home/user/esp/esp-mdf/esp-idf/components/esp32/cpu_start.c:274

I (0) cpu_start: App cpu up.
I (291) heap_init: Initializing. RAM available for dynamic allocation:
I (298) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (304) heap_init: At 3FFB39E8 len 0002C618 (177 KiB): DRAM
I (310) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (317) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (323) heap_init: At 4008B6E8 len 00014918 (82 KiB): IRAM
I (329) cpu_start: Pro cpu start user code
I (347) spi_flash: detected chip: generic
I (348) spi_flash: flash io: dio
W (357) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (360) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (376) enc28j60: revision: 6
I (396) esp_eth.netif.glue: 02:00:00:12:34:56
I (396) esp_eth.netif.glue: ethernet attached to netif
I (406) eth_example: Ethernet Started
I (2406) enc28j60: working in 10Mbps
I (2406) enc28j60: working in half duplex
I (2406) eth_example: Ethernet Link Up
I (2406) eth_example: Ethernet HW Addr 02:00:00:12:34:56
I (3376) esp_netif_handlers: eth ip: 192.168.3.151, mask: 255.255.255.0, gw: 192.168.3.1
I (3376) eth_example: Ethernet Got IP Address
E (3376) enc28j60: emac_enc28j60_transmit(766): last transmit still in progress
I (3376) eth_example: ~~~~~~~~~~~
I (3386) eth_example: ETHIP:192.168.3.151
I (3396) eth_example: ETHMASK:255.255.255.0
I (3396) eth_example: ETHGW:192.168.3.1
I (3406) eth_example: ~~~~~~~~~~~
I (542406) eth_example: Ethernet Link Down
I (548406) enc28j60: working in 10Mbps
I (548406) enc28j60: working in half duplex
I (548406) eth_example: Ethernet Link Up
I (548406) eth_example: Ethernet HW Addr 02:00:00:12:34:56
I (552876) esp_netif_handlers: eth ip: 192.168.3.151, mask: 255.255.255.0, gw: 192.168.3.1
I (552876) eth_example: Ethernet Got IP Address
I (552876) eth_example: ~~~~~~~~~~~
I (552876) eth_example: ETHIP:192.168.3.151
I (552886) eth_example: ETHMASK:255.255.255.0
I (552886) eth_example: ETHGW:192.168.3.1
I (552896) eth_example: ~~~~~~~~~~~
I (568406) eth_example: Ethernet Link Down
I (572406) enc28j60: working in 10Mbps
I (572406) enc28j60: working in half duplex
I (572406) eth_example: Ethernet Link Up
I (572406) eth_example: Ethernet HW Addr 02:00:00:12:34:56
I (576876) esp_netif_handlers: eth ip: 192.168.3.151, mask: 255.255.255.0, gw: 192.168.3.1
I (576876) eth_example: Ethernet Got IP Address
I (576876) eth_example: ~~~~~~~~~~~
I (576876) eth_example: ETHIP:192.168.3.151
I (576886) eth_example: ETHMASK:255.255.255.0
I (576886) eth_example: ETHGW:192.168.3.1
I (576896) eth_example: ~~~~~~~~~~~

Other items if possible

About this issue

  • Original URL
  • State: closed
  • Created 4 years ago
  • Comments: 52 (19 by maintainers)

Most upvoted comments

Just note that I recommend to use the ENC in the Full Duplex mode. There is an option in Menuconfig to enable it now. You need to set the Full duplex at the remote node (your computer/switch) manually too. E.g. if you use Ubuntu run the following command sudo ethtool -s INTERFACE_NAME speed 10 duplex full autoneg off

I addressed the Half Duplex Errata but the performance is poor, especially for TCP connection.

+1
kostaond on Jul 20, 2021

@nx518 I am also moving on from this. It’s pretty unusable in its current state for anything requiring more than minimal throughput. Tried to get a hold of @suda-morris and @hendog82 to see if they had any further ideas, but I think they’ve been busier with other projects.

Moving on to the DM9051. That has been integrated for longer, and appears to have a MUCH smaller errata than the enc28j60. You can buy it from LCSC. https://lcsc.com/product-detail/Ethernet-ICs_DAVICOM_DM9051NP_DAVICOM-DM9051NP_C113756.html

Example schematic for the dm9051: https://www.dacomwest.de/images/Dateien/Davicom/Dokumente/MAC-PHY-Controller/DM9051/DM9051_demo_v2.1.pdf

+1
lucastcox on Jun 6, 2020

@nx518, I decided to stop trying to make it workable, I ordered Wiznet w5500 modules and when it will arrive I will try to make driver for it, but it will be may be by the end of summer, I have some urgent projects for now

+1
no1seman on Jun 4, 2020

So, still can’t got it work on SPI speed greater than 6 Mhz, but made some errata issues fixes:

  1. Disabled forcing fullduplex;
  2. Fixed errata issue 6 by adding additional checks to ISR task;
  3. Fixed errata issue 12 by adding reset of internal transmit logic to transmit function logic;
  4. Fixed errata issue 13 by adding polling cycle to transmit function logic.

Full project code will be found here: https://github.com/no1seman/enc28J60_esp32_idf

Need smbd to test and code review.

With this code got no errors except one:

D (2878) esp_netif_lwip: esp_netif_dhcpc_start_api esp_netif:0x3ffb98cc
D (2878) esp_netif_lwip: esp_netif_start_ip_lost_timer esp_netif:0x3ffb98cc
D (2888) esp_netif_lwip: if0x3ffb98cc start ip lost tmr: no need start because netif=0x3ffb994c interval=120 ip=0
D (2898) esp_netif_lwip: starting dhcp client
E (2918) enc28j60: emac_enc28j60_transmit(1179): last pending transmit cancelled due to timeout
D (2928) esp_netif_lwip: call api in lwip: ret=0x0, give sem
D (2928) event: running post ETH_EVENT:2 with handler 0x400d5318 and context 0x3ffb9bf4 on loop 0x3ffb89a4
0x400d5318: eth_event_handler at /home/user/esp/enc28j60/build/../main/enc28j60_example_main.c:28

I (2938) eth_example: Ethernet Link Up
I (2938) eth_example: Ethernet HW Addr 02:00:00:12:34:56
D (3748) esp_netif_lwip: esp_netif_dhcpc_cb lwip-netif:0x3ffb994c
D (3748) esp_netif_lwip: if0x3ffb98cc ip changed=1
D (3748) event: running post IP_EVENT:4 with handler 0x400d81f4 and context 0x3ffb9bc8 on loop 0x3ffb89a4
0x400d81f4: esp_netif_action_got_ip at /home/user/esp/esp-mdf/esp-idf/components/esp_netif/esp_netif_handlers.c:93

It’s not clear why dhcp client tries to send any data to interface before linkup event. In that case error is a normal behaviour.

+1
no1seman on Mar 17, 2020

After adding second ‘ping’ from other console got the following errors: E (902406) enc28j60: emac_enc28j60_read_phy_reg(438): phy is busy E (902406) enc28j60: enc28j60_update_link_duplex_speed(92): read PHSTAT2 failed E (902406) enc28j60: enc28j60_get_link(131): update link duplex speed failed

+1
no1seman on Feb 11, 2020
Read more comments on GitHub
← esp-idf: DPP Auth Failed on dpp-enrollee example (IDFGH-9228)
esp-idf: esp-idf dhcp client gives different ip each time we boot, arduino-esp32 does not →