[CYW43] got unexpected packet -9

[peterharperuk]

If you send udp messages quickly (e.g. one every 10ms or less), you see a lot of these messages.

[CYW43] got unexpected packet -9

See #33 for the original reporter and the attached modification to raspberrypi/pico-examples#275, which also repros the problem.

#0 cyw43_ll_process_packets (self_in=self_in@entry=0x20000fa0 <cyw43_state>)
at /home/peterh/source/pico/pico-sdk/lib/cyw43-driver/src/cyw43_ll.c:1160
#1 0x1000382e in cyw43_poll_func () at /home/peterh/source/pico/pico-sdk/lib/cyw43-driver/src/cyw43_ctrl.c:236
#2 0x1000087c in low_priority_irq_handler ()
at /home/peterh/source/pico/pico-sdk/src/rp2_common/pico_cyw43_arch/cyw43_arch_threadsafe_background.c:143
#3
#4 to_us_since_boot (t=...) at /home/peterh/source/pico/pico-sdk/src/common/pico_base/include/pico/types.h:48
#5 time_reached (t=...) at /home/peterh/source/pico/pico-sdk/src/rp2_common/hardware_timer/include/hardware/timer.h:115
#6 sleep_until (t=...) at /home/peterh/source/pico/pico-sdk/src/common/pico_time/time.c:361
#7 0x10005214 in sleep_us (us=) at /home/peterh/source/pico/pico-sdk/src/common/pico_time/include/pico/time.h:102
#8 0x1000524e in sleep_ms (ms=ms@entry=100) at /home/peterh/source/pico/pico-sdk/src/common/pico_time/time.c:393
#9 0x1000038a in run_udp_beacon () at /home/peterh/source/pico/pico-examples/pico_w/udp_beacon/picow_udp_beacon.c:55
#10 0x10000434 in main () at /home/peterh/source/pico/pico-examples/pico_w/udp_beacon/picow_udp_beacon.c:77

The -9 error comes from here...

#0 sdpcm_process_rx_packet (self=self@entry=0x20000fa0 <cyw43_state>, buf=buf@entry=0x20000fbc <cyw43_state+28> "",
out_len=out_len@entry=0x20041f40, out_buf=out_buf@entry=0x20041f44)
at /home/peterh/source/pico/pico-sdk/lib/cyw43-driver/src/cyw43_ll.c:912
#1 0x10002486 in cyw43_ll_sdpcm_poll_device (self=self@entry=0x20000fa0 <cyw43_state>, len=len@entry=0x20041f40,
buf=buf@entry=0x20041f44) at /home/peterh/source/pico/pico-sdk/lib/cyw43-driver/src/cyw43_ll.c:1140
#2 0x10002532 in cyw43_ll_process_packets (self_in=self_in@entry=0x20000fa0 <cyw43_state>)
at /home/peterh/source/pico/pico-sdk/lib/cyw43-driver/src/cyw43_ll.c:1150
#3 0x1000382a in cyw43_poll_func () at /home/peterh/source/pico/pico-sdk/lib/cyw43-driver/src/cyw43_ctrl.c:236
#4 0x1000087c in low_priority_irq_handler ()
at /home/peterh/source/pico/pico-sdk/src/rp2_common/pico_cyw43_arch/cyw43_arch_threadsafe_background.c:143
#5
#6 to_us_since_boot (t=...) at /home/peterh/source/pico/pico-sdk/src/common/pico_base/include/pico/types.h:48
#7 time_reached (t=...) at /home/peterh/source/pico/pico-sdk/src/rp2_common/hardware_timer/include/hardware/timer.h:115
#8 sleep_until (t=...) at /home/peterh/source/pico/pico-sdk/src/common/pico_time/time.c:361
#9 0x10005210 in sleep_us (us=) at /home/peterh/source/pico/pico-sdk/src/common/pico_time/include/pico/time.h:102
#10 0x1000524a in sleep_ms (ms=ms@entry=10) at /home/peterh/source/pico/pico-sdk/src/common/pico_time/time.c:393
#11 0x1000038a in run_udp_beacon () at /home/peterh/source/pico/pico-examples/pico_w/udp_beacon/picow_udp_beacon.c:55
#12 0x10000434 in main () at /home/peterh/source/pico/pico-examples/pico_w/udp_beacon/picow_udp_beacon.c:77

(gdb) info lo
bdc_header = 0x20000fc8 <cyw43_state+40>
payload = 0x20000fcc <cyw43_state+44> "\204\200"
len = 240
header = 0x20000fbc <cyw43_state+28>

(gdb) p *bdc_header
$4 = {flags = 0 '\000', priority = 0 '\000', flags2 = 0 '\000', data_offset = 0 '\000'}

(gdb) p *header
$3 = {size = 256, size_com = 65279, sequence = 58 ':', channel_and_flags = 1 '\001', next_length = 0 '\000', 
  header_length = 12 '\f', wireless_flow_control = 0 '\000', bus_data_credit = 98 'b', reserved = "\000"}

(gdb) x/240b 0x20000fcc
0x20000fcc <cyw43_state+44>:	0x84	0x80	0x00	0x00	0x00	0x00	0x00	0x10
0x20000fd4 <cyw43_state+52>:	0x00	0x00	0x00	0x00	0x00	0x00	0x00	0x00
0x20000fdc <cyw43_state+60>:	0x0c	0x24	0x05	0x00	0x00	0x00	0x00	0x00
0x20000fe4 <cyw43_state+68>:	0x67	0xd8	0x8f	0x00	0x00	0x00	0x00	0x00
0x20000fec <cyw43_state+76>:	0x08	0x82	0x84	0x8b	0x96	0x8c	0x12	0x98
0x20000ff4 <cyw43_state+84>:	0x24	0x03	0x01	0x0b	0x2a	0x01	0x00	0x32
0x20000ffc <cyw43_state+92>:	0x04	0xb0	0x48	0x60	0x6c	0x0b	0x05	0x05
0x20001004 <cyw43_state+100>:	0x00	0x5d	0x12	0x7a	0x46	0x05	0x73	0xd0
0x2000100c <cyw43_state+108>:	0x00	0x00	0x0c	0x2d	0x1a	0xac	0x41	0x1b
0x20001014 <cyw43_state+116>:	0xff	0xff	0xff	0x00	0x00	0x00	0x00	0x00
0x2000101c <cyw43_state+124>:	0x00	0x00	0x00	0x00	0x01	0x00	0x39	0x00
0x20001024 <cyw43_state+132>:	0x00	0x00	0xd0	0x00	0x00	0x00	0x39	0x00
0x2000102c <cyw43_state+140>:	0x00	0x00	0xc8	0x01	0x52	0x00	0x41	0x00
0x20001034 <cyw43_state+148>:	0x02	0x10	0x02	0x00	0x00	0x00	0x00	0x00
0x2000103c <cyw43_state+156>:	0x09	0x00	0x14	0x06	0x00	0x00	0x00	0x00
0x20001044 <cyw43_state+164>:	0x00	0x00	0x00	0x00	0x00	0x00	0x00	0x00
0x2000104c <cyw43_state+172>:	0x00	0x00	0x00	0x00	0xfc	0xec	0xda	0xa1
0x20001054 <cyw43_state+180>:	0x6b	0x5e	0xea	0x02	0x00	0x00	0x00	0x00
0x2000105c <cyw43_state+188>:	0x00	0x00	0x00	0x00	0x0a	0x04	0xf0	0x00
0x20001064 <cyw43_state+196>:	0x1e	0x00	0x3a	0x01	0x00	0x00	0x00	0x00
0x2000106c <cyw43_state+204>:	0x00	0x00	0x00	0x00	0x00	0x00	0x00	0x00
0x20001074 <cyw43_state+212>:	0x00	0x00	0x0b	0x0e	0x00	0x00	0x00	0x00
0x2000107c <cyw43_state+220>:	0x00	0x00	0x00	0x00	0x00	0x00	0x00	0x00
0x20001084 <cyw43_state+228>:	0x00	0x00	0x00	0x00	0x00	0x00	0x00	0x00
0x2000108c <cyw43_state+236>:	0x00	0x00	0x00	0x00	0x00	0x00	0x00	0x00
0x20001094 <cyw43_state+244>:	0x00	0x00	0x00	0x00	0x00	0x00	0xc9	0x03
0x2000109c <cyw43_state+252>:	0x00	0x00	0x00	0x00	0xc8	0x01	0x2c	0x00
0x200010a4 <cyw43_state+260>:	0xfc	0xec	0xda	0xa1	0x6b	0x5e	0x28	0xcd
0x200010ac <cyw43_state+268>:	0xc1	0x00	0x0c	0x01	0xfc	0xec	0xda	0xa1
0x200010b4 <cyw43_state+276>:	0x6b	0x5e	0x00	0x00	0x07	0x00	0x00	0x00

So it seems to be mostly blank where it shouldn't be. It doesn't look like an ethernet packet. They don't do any harm as they're ignored but they must waste time. I think we'll have to reproduce this and ask Infineon. I think we should be able to send 10 UDP packets a second?!

0001-Modify-beacon-example-to-reproduce-unexpected-packet.patch.gz

[peterharperuk]

Its 100 udp packets per second that seems to cause the problem - still not unreasonable? I can reproduce it in the Infineon example code so will report it to them now.

[tjko]

100 packets/sec seems still very 'slow' rate, would expect it to be able to handle much more.... (I ran some quick tests with RPi Zero and it easily transmitted around 5000 packets/second with small UDP packets...)

[dpgeorge]

I've been trying to reproduce this issue but cannot. I didn't get to building the picow_udp_beacon.c because it seems I need to downgrade GCC to below version 11.3. Instead I tried to reproduce in MicroPython, but without any luck:

• Running iperf3.client('192.168.0.xx', udp=True, bandwidth=10*1024*1024) doesn't show any errors.
• running a simple while-true loop with s.sendto(bytearray(128), ('192.168.0.xx', 4444)) (in an attempt to mimic picow_udp_beacon.c) also doesn't show any errors (with no delay, and a 10ms delay in the loop).

I can try to get picow_udp_beacon.c building and running next.

[dpgeorge]

Update: I can reproduce the problem using picow_udp_beacon.c, in both polling and background mode. I get the error even with a 50ms delay between sending UDP packets.

[dpgeorge]

Update: I can now reproduce with MicroPython (with debug prints enabled!, it seems they aren't enabled by default) and the following script:

import time
import socket
s=socket.socket(socket.AF_INET, socket.SOCK_DGRAM)
while True:
    print('send')
    s.sendto(bytearray(128), ('192.168.0.xx', 4444))
    time.sleep(0.080)

80ms between loops seems to be the limit at which it starts to happen.

There also seems to be a semi-regular pattern where the error is printed every 13 UDP packets.

[peterharperuk]

It'll happen more regularly the more data you send. I've reproduced it with TCP using iperf using two interfaces if you receive on one and send on the other - bit weird.

[peterharperuk]

@dpgeorge I should point out that the driver is not at fault here - I can reproduce this problem with Infineon's code base.

[dpgeorge]

I can reproduce this problem with Infineon's code base.

Yes I saw your earlier comment about that.

I cannot reproduce the problem with the Murata 1DX and the w4343WA1_7_45_98_50_combined.h firmware. So it's specific to the SPI interface and/or the w43439A0_7_95_49_00_combined.h firmware.

This spurious packet is always 240 bytes long and is being detected as an async event (as opposed to control or data packet). I suspect it could be debugging and/or profiling information sent back from the WiFi processor. In that case it's probably safe to ignore (and the original WICED WWD driver does ignore such packets, albeit after printing a debug message).

[tjko]

I just happen to notice that with SDK 1.5.0, I seem to only get these errors with "Release" builds:

[CYW43] got unexpected packet -9

While "Debug" builds I don't seem to see these. That seems odd?

[peterharperuk]

I can see it in debug. I suspect you were just "unlucky".

Later: The problem goes away for me if I enabled stdio usb. I do wonder if we're provoking the problem - maybe by making too many requests or something.