search

georgerobotics / cyw43-driver

Other
79 stars 42 forks source link

[CYW43] got unexpected packet -9 #36

Closed peterharperuk closed 1 year ago

peterharperuk commented 2 years ago

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 https://github.com/georgerobotics/cyw43-driver/issues/33 for the original reporter and the attached modification to https://github.com/raspberrypi/pico-examples/pull/275, which also repros the problem.

0 cyw43_ll_process_packets (self_in=self_in@entry=0x20000fa0 )

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 , 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 , 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 )

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 commented 2 years ago

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 commented 2 years ago

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 commented 1 year ago

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:

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

dpgeorge commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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

dpgeorge commented 1 year ago

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 commented 1 year ago

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 commented 1 year ago

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.