W5500 - Lots of UDP RX traffic resulting in networking failure

[coledeck]

Hi,

I have some code that uses W5500 ethernet, and listens for UDP packets with the E1.31 protocol.
The W5500 is wired identical to the EVB-W5500-pico board, so SPI wired in, as well as the interrupt pin, and is setup with

Wiznet5500lwIP eth(17, SPI, 21); // 17 : cs, 21 : INTn

...
    eth.config(IP_ADDR, INADDR_NONE); // set static IP, no DNS (LAN IP comms only)
    SPI.setRX(16);
    SPI.setCS(17);
    SPI.setSCK(18);
    SPI.setTX(19);
    eth.setSPISpeed(10000000);
    lwipPollingPeriod(3);
    eth.setHostname(HOSTNAME);
    
    if (!eth.begin()) {
        Serial.println("No wired Ethernet hardware detected. Check pinouts, wiring.");
        return false;
    }

The packet sizes max out at around 640 bytes. The system is getting these UDP packets 30+ times per second, and calls udp.parsePacket(); and udp.readBytes(pwbuff->raw, size); pretty darn often - more often than we are getting a packet I'm pretty sure. (I did not write this part of the code - it's part of a library).

But after some amount of time, sometimes it's 30 minutes, sometimes it's 30 seconds, it seems the entire network stack has crashed (?). No more UDP packets get past udp.parsePacket(), no longer responds to pings, no response on HTTP server (not related to crash btw, i can hit http as much as I want without issue until UDP breaks everything), etc. Both pico cores keep running just fine, but I don't get any packets - they are still hitting the W5500 i think, because it knows there's a packet to look for, the status LED changes, but udp.parsePacket() returns 0. Using picoprobe, I can see that the code that returns zero is

bool next() {
        if (!_rx_buf) {
            return false; // right here
        }
...

in https://github.com/earlephilhower/arduino-pico/blob/master/libraries/WiFi/src/include/UdpContext.h#L241

AKA there is no _rx_buf after some period of time anymore(?)

So my questions are;

does this mean the w5500 / lwip / something ran out of buffers for rx?

and if so is there a way to increase the number of, or size of buffers;

or do I need to process packets faster before they fill up?

or am I looking in the wrong place and this is not the issue? could it be the W5500 resetting or something unrelated?

basically, any ideas how can I prevent this from happening, or how to debug it further / better? It is okay if I have to drop a packet in order to get the latest one or whatnot; I'd rather that happen than networking completely dying.

Much appreciated,
Cole

[JAndrassy]

I see something similar while I test the new alternative WiFi driver, which is integrated as the wired network interfaces are. (the cw34 on Pico W has a different integration).
I now switched to enc28j60 to test if the problem is the new driver, but I didn't have time yet to do the test.

[earlephilhower]

Very odd. The implementation of wired Ethernet here uses the same async_context that the PicoW wireless uses for its periodic polling of the drivers. (The CYW43 WiFi also has IRQ-based reception which isn't implemented for wired devices yet). As part of my testing I ran the AdvancedWebServer script on a W5100 for ~24hrs being polled by between 1 and 3 web servers every 5 seconds w/o any particular incident.

The internal LWIP and WiFiUDP/WiFiClient stuff is absolutely identical and doesn't have any idea where the packets come from or go out to.

Do you have a way of reproducing this w/o your whole app? Maybe something w/netcat on the PC side and a simple UDP receiver sketch on the Pico?

You can check a few things simply, assuming you have a Picoprobe:

• When you're in the "no more packets" state you can set a breakpoint on ethernet_timeout_reached and the W5500 LwipIntfDev<>::handlePackets (the name will be the templated expansion but will have that general format).
• The timeout-reached function is called every 20ms, but if it's not firing then that points to the async context dying somehow.
• If it's firing every 20ms but you never see a packet received in the ::handlePackets that could point to pbuf exhaustion (single step and if the pbuf_alloc fails that's it and an easy change/fix).
• • If the readFrameSize call always comes back 0 in that function, the W5500 itself isn't signaling that it has any data to read and is the cause.

[coledeck]

Genuinely haven't managed to make it hang at this CPU + SPI clock yet. Let me see if slowing one thing down will definitely cause it and then i can make a simple test program. Got it to crash once!

[coledeck]

OK, so ethernet_timeout_reached is getting called normally. handlePacket gets triggered as well. readFrameSize() does return a size, 682, which corresponds with the actual packet size of a real, valid packet. (but it does not make it to my packet validation function). So the W5500 seems to be working.

pbuf_alloc gets called and stepping into there i get thrown into asm. not sure if it's helpful but payload_len goes to 696, then after a while p (buffer I guess) is created and has a tot_len of 666, len 666, and p.next is tot_len 53, len 0. Then p is "optimized out", and i bounce another instruction or 2, and then it returns, something surely, not sure how to see what if anything (i'm relatively new to debugging like this if you can't tell :P)

[earlephilhower]

The only thing I was hoping to check was that the pbuf_alloc succeeded, no need to step into it in ARM Thumb assembly 😆 . As long as it's not returning 0 (and the packet being discarded) you're okay. Given what you described I'm seeing nothing wrong. The periodic timer is firing, the W5500 is returning data, and the pbuf is allocated and thrown up the stack to the LWIP handlers.

Looks like I will need an MCVE that can run w/o extra HW to help debug this. Once it's in LWIP it's kind of a black box. FWIW if LWIP memory was corrupted it would most likely have completely panic crashed the core so I'm disinclined to think it's that. Don't really have any other suggestions now, but I'll think on it...

[coledeck]

Alright, I'll get to work on a simplified MCVE that I can get crashing. Do you have a W5500 / other ethernet module?

Would a small python file for sending the UDP packets ok? I'll just make a dependency-free single-file version of what I'm using now if that's fine.

[earlephilhower]

A Python script to drive it would be fine. I've got an official WizNet W5100 board (they were nice enough to send me one back when the core just came out) which I trust and always seems to work, and some "W5500" add-on boards from AliExpress that I'm not so sure of. They do seem to work but occasionally they won't even start up and require a few powercycles before they appear on the SPI bus.

If it's endemic to the lwipEthernet configuration then W5100 or W5500 shouldn't matter, so I'd prefer to stick w/the official WizNet board I've got.

[JAndrassy]

a Wireshark session of the crash with W5500:
rp2040-w5500.pcapng.zip

It crashes the same way with the ESPHost WiFi, but it doesn't crash with Pico W

[earlephilhower]

Thanks, but to clarify things: By "crash" do you mean a HW exception/panic, or just it isn't answering or processing a packet you expect it to?

What exactly am I looking at with the pcap? What are the IPs of the sender/Pico? What is being sent (looking for DHCP request? DNS? TCP?)?

[JAndrassy]

the sketch does modbus requests. what I see as first is that ACK are sent late. the server resent the packet. at first the ACK is sent when the server already resent the packet, later it gets worse.
I think the ACK are late because the received packets are processed late. The sketch waits two seconds for the response, but the response is there when the sketch wants to read the response for the next request.
my sketch stops the connection when there are too many responses missed so that is the first RST (red line) in the Wireshark records.
then the connection can't be established again. SYNC from server is resent, then ACK from RP2040 is sent twice and then the connection is RST by RP2040 (I didn't check yet if the sketch does it or the lwip) .

by crash I meant that it can't connect again.

[coledeck]

OK @earlephilhower got a little MCVE for ya. While making it I discovered, I think, that keeping MDNS & httpServer open (no connections though - unless Windows 10 is randomly doing some query) seems to drastically speed up the lwip crash. Maybe it's MDNS sending out packets here and there that's breaking it, not sure. (mDNS without HTTP didn't seem to do anything different though). So I kept that in. Experiment with polling rate, SPI rate, MDNS/http on/off, but as-is how I'm sending it, it crashes for me pretty consistently in under 20 seconds. Without MDNS/HTTP on it takes longer, but still crashes.

Serial (USB) prints some basic info; if we are getting full packets or not. When it switches from "Got valid packet of size 638" to "No packets received in a while" (and the python script is still running) is when it breaks.

pinouts should be the same as w5100s/w5500 EVP pico board, I'm using w5500 official "w5500-io" chip soldered to a PCB with matching pinouts for reference.
pico code: https://cdn.deck.sh/file/pubcdn/files/jukebox/main.cpp

platformio.ini:

...
platform_packages = 
	framework-arduinopico@https://github.com/earlephilhower/arduino-pico.git#c64a4a58d793ee6d24c7df7ff3ec35adac3bbb45
board_build.core = earlephilhower
debug_tool = cmsis-dap
upload_protocol = cmsis-dap
monitor_speed = 115200
board_build.filesystem_size = 1m 
board_build.f_cpu = 133000000L
...

Python code - should work on linux or windows, just fine, I did it from WSL2. needs python3 package sacn.
https://cdn.deck.sh/file/pubcdn/files/jukebox/udp_send_test.py
Change ipaddr to the pico's IP. 70fps seemed to be pretty good but on my machine I can push 100+ fps (actually packets per second, nothing is actually displayed of course).

I'm connected directly between my laptop and pico with a cable, static IP on both sides, but going thru a switch, laptop on wifi, dhcp, etc does not matter. You can change line 79 in the pico code to change IP.

Thanks soo much for your help!! let me know if there's any questions or issues getting it running :)

[coledeck]

So far so good.... I'll leave it running overnight and do a bit more slamming with a bajillion packets but it's looking good! You're the best Earle!!

[earlephilhower]

Cool, thx for the update. I'm at 1hr now, no hiccups that I can see. Probably merge tomorrow and do a dot-release.

[coledeck]

Gonna give myself a migraine with all these flashing LEDs 😂 - currently sending as many fully valid, randomized, lighting packets as my PC can generate, which according to wireshark, is around 9000 packets per second. Also wget-ing the HTTP service in a while loop for fun. Watchdog disabled.

And I'm sure a very large amount of these packets are getting ignored - up to about 1000fps could be making it in theory but I'm guessing more like 250-500 are making it beyond LWIP - all I know is the LEDs are refreshing and burning my eyes scarily fast, but no crashes about 10 minutes in of this.

[earlephilhower]

I'm at 6hrs now w/o any hiccups, so have done the merge. At the very least it's a massive improvement. Please update when you get a chance (and assuming you're not incapacitated by migraines! 😆

[coledeck]

Well, it's definitely made a huge improvement as you said!! woohoo! Thank you so much!! is there a way to donate toward you/this project??? you're spending way more time on this than i would if I wasn't getting paid :P

....though I fear there may actually be another bug in here. I'll be looking more into it tomorrow, but there's some funky stuff going on. It survives the 9000 packet per sec, spam http, etc hellhole no frickin problem, but in some cases it is still kinda dying only at a normal-ish 60-120fps actual data stream. It's possible it's like a corrupted packet or something being handled wrong any my code is crashing, and I haven't been able to replicate it with the MCVE code - only my full LED code it happens sometimes (and still much rarer than prior crashes!) so I'll dig a bit further into that tomorrow.

Regardless - you found one pretty sneaky bug so that is just great!! Thank you Earle!

[JAndrassy]

[JAndrassy]

the problem is still there. after a time ACK start to go out late and after a stop() the client can't connect again even with longer timeout

[JAndrassy]

I test with the new release with an enc28j60. handlePackets stops for extended time and that causes problems.
first value in following log is millis()

59018 client.write id 21  // modbus request with id 21
59018 out: 66  // LwipIntfDev<RawDev>::linkoutput_s  modbus request
59019 client.readBytes
59046 in: 64  // RawDev::readFrameSize() ACK from modbus server
59227 in: 183  // RawDev::readFrameSize() response from modbus server
59230 client.write id 22
59230 out: 66  // request 22 and ACK for response 21
59231 client.readBytes
59269 in: 64  // ACK
59369 ><  // 500 millis 'blink' from LwipIntfDev<RawDev>::handlePackets
59450 in: 71  // response
59451 client.write id 23
59451 out: 66  // request
59452 client.readBytes
59491 in: 64  // ACK
59852 in: 99  // response
59893 ><
59893 out: 54  // ACK
60053 client.write id 24
60053 out: 66  // request
60053 client.readBytes
60074 in: 64  // ACK
60396 ><
60516 in: 77  // response
60677 out: 54  // ACK
60899 ><
61400 ><
67018 client.write id 25
67018 ><
67018 handlePackets was paused 5517 millis. last run was at 61501  // logged in handlePackets
67018 in: 64  // ARP Who has ...
67019 out: 42  // ARP .. is at ...
67019 in: 64  // ARP Who has ...
67019 out: 42  // ARP .. is at ...
67020 in: 64  // ARP Who has ...
67020 out: 42  // ARP .. is at ...
67021 out: 66  // request id 25
67021 client.readBytes
72021 no response  // from sketch
72079 client.write id 26  // next attempt
72080 ><
72080 handlePackets was paused 5060 millis. last run was at 67020
72080 in: 64  // ACK for request 25
72081 out: 66  // request id 26
72082 in: 183  // response id 25
72083 in: 183  // response id 25
72083 out: 54  // ACK for response id 25
72084 in: 183  // response for id 25
72085 out: 54  // ACK for response id 25
72085 in: 183  // response for id 25
72086 out: 54  // ACK for response id 25
72086 client.readBytes
previous response read. id  25  // from sketch 
72088 client.readBytes
77088 no response
77146 client.write id 27  // next attempt
77146 ><
77146 handlePackets was paused 5060 millis. last run was at 72086
77147 in: 64  // ACK for request 26
77148 out: 66  // request 27
77148 in: 183  // response 26
77149 in: 183  // response 26
77150 out: 54  // ACK for 26
77151 client.readBytes
previous response read. id  26
...

[JAndrassy]

handlePackets is not called for 5 seconds. but when I had client.setTimeout(2000), it was 2 seconds. but I couldn't find how is it related.
yes I try to make an MCVE tomorrow

[earlephilhower]

The only way that could happen is if something held the big LWIP lock for 5 seconds straight. The async context fires off a periodic interrupt but if someone already has the lock it punts to the next cycle (since they just interrupted someone in the middle of non-reentrant LWIP code). Does your code manually grab the Ethernet/LWIP lock?

[JAndrassy]

when handlePackets stops it is only executed after client.write. so the time between calls to handlePackets is the timeout of readBytes which is between the two client.write occurrences. I don't know why handlePackets then executes only after client.write.

LwipIntfDev::linkoutput_s can't get a lock in that client.write so it is a problem with the lock

now I know that handlePackets is executed with ethernet_timeout_worker from async_context. and now there it is always_pending_update_timeout_worker which doesn't really help as I see it.

async_context_threadsafe_background_t uses low priority interrupt. maybe the low priority is the problem with my sketch. when I remove LittleFS initialization it runs much much longer. with LittleFS it fails almost immediately.

Pico W doesn't use handlePackets. the functions called from handlePackets are not implemented. the packets are read somewhere else. but handlePackets is invoked periodically

the only uses of ethernet_arch_lwip_begin in the running sketch are in LwipIntfDev::linkoutput_s and in LWIPMutex. the other uses in lwIP_Xy are used for begin or not at all in the sketch.

the sketch is my project from 2017 which since then run on many different Arduino networking libraries. I could always solve the problems. The sketch has 3 servers (OTA, Web, Telnet), permanent modbus connection and connection to Blynk Cloud. It does some additional short connections as client

the project is not active anymore. I just used it to test the (lwP_)ESPHost library now and compare it with other lwIP_Xy

EDIT: it run more than a hour when I stopped it to test again with LittleFS.begin();. With LittleFS.begin(); the problem starts soon with his sketch. But I can leave LittleFS.begin() if I remove the LedBar code. So the problem is just too much happening in the sketch (even it is only in monitoring mode, not driving the Triac and not reading the current sensor ). now I see why it is good to have the TCP/IP stack in the network adapters firmware. The same sketch runs with WiFiNINA without problems.

[earlephilhower]

It's definitely possible to make the WizNet (maybe ENC, haven't looked at datasheet) drivers IRQ based instead of polling, but IRQs weren't implemented in the 8266 where I took them from and there's only so much time in a day. :) We'd need to disable the GPIO interrupt on that pin while holding the lwip lock, but OTW it seems straightforward.

Anyway, which of those sketches in your repo are you running and having the 5s freeze? It seems that there should be no reason for holding a lock so long, so maybe there's a simple fix to some of the WiFiClient/WiFiUDP objects.

[JAndrassy]

I run the Regulator sketch with modifications for lwIP_Xy. nothing you could run unless you have a Fronius inverter system.
(all the ino files in the Regulator folder are one sketch)

It runs now as lwIP_ESPHost test. It is up 9 hours now. Free RAM is stable.

The LedBar module must be commented out from setup() and loop(). With LedBar the handlePackets didn't run periodically. The Grove_LED_Bar library is simple. For a short moment sends a few bytes with digitalWrite while doing clock signal with digitalWrite on a second pins. The sketch updates the LedBar only once in a second.