search

soypat / cyw43439

Driver for the Wifi+bluetooth integrated circuit on the pico.
MIT License
119 stars 6 forks source link

invalid csum error, server stops #30

Closed scottfeldman closed 7 months ago

scottfeldman commented 10 months ago

Running examples/tcpserver, hit this:

sfeldma@nuc:~/work/cyw43439$ tinygo flash -monitor -target pico -stack-size=32kb -size short ./examples/tcpserver/
   code    data     bss |   flash     ram
 428520   17084    3824 |  445604   20908
Connected to /dev/ttyACM0. Press Ctrl-C to exit.
starting program
time=1970-01-01T00:00:02.002Z level=INFO msg=Init:start
time=1970-01-01T00:00:03.556Z level=INFO msg=Init:done took=1.552879s
time=1970-01-01T00:00:03.557Z level=INFO msg=joinWpa2 ssid=test len(pass)=8
time=1970-01-01T00:00:07.002Z level=INFO msg=rxEvent event=AUTH status=0 reason=0 flags=0 dev.linkstate=1
time=1970-01-01T00:00:07.003Z level=INFO msg=rxEvent event=SET_SSID status=0 reason=0 flags=0 dev.linkstate=2

MAC: 28:cd:c1:01:13:7c
dhcp ongoing...
time=1970-01-01T00:00:07.009Z level=INFO msg=DHCP:tx msg=Discover
time=1970-01-01T00:00:07.059Z level=INFO msg=DHCP:rx msg=Offer
time=1970-01-01T00:00:07.060Z level=INFO msg=DHCP:tx msg=Request
time=1970-01-01T00:00:07.110Z level=INFO msg=DHCP:rx msg=Ack
DHCP complete IP: 10.0.0.122
start listening on: 10.0.0.122:1234
time=1970-01-01T00:00:08.028Z level=INFO msg=TCP:rx-statechange port=1234 old=SynSent new=SynRcvd rxflags=[SYN]
time=1970-01-01T00:00:08.079Z level=INFO msg=TCP:rx-statechange port=1234 old=SynRcvd new=Established rxflags=[ACK]
time=1970-01-01T00:10:31.560Z level=ERROR msg=Stack.RecvEth err="invalid TCP/UDP checksum"
time=1970-01-01T00:10:31.561Z level=ERROR msg=tryPoll:rx plen=0 err="invalid TCP/UDP checksum"
poll error: invalid TCP/UDP checksum
time=1970-01-01T00:10:31.818Z level=ERROR msg=Stack.RecvEth err="invalid TCP/UDP checksum"
time=1970-01-01T00:10:31.818Z level=ERROR msg=tryPoll:rx plen=0 err="invalid TCP/UDP checksum"
poll error: invalid TCP/UDP checksum
time=1970-01-01T00:10:32.432Z level=ERROR msg=Stack.RecvEth err="invalid TCP/UDP checksum"
time=1970-01-01T00:10:32.433Z level=ERROR msg=tryPoll:rx plen=0 err="invalid TCP/UDP checksum"
poll error: invalid TCP/UDP checksum
time=1970-01-01T00:10:33.557Z level=ERROR msg=Stack.RecvEth err="invalid TCP/UDP checksum"
time=1970-01-01T00:10:33.558Z level=ERROR msg=tryPoll:rx plen=0 err="invalid TCP/UDP checksum"
poll error: invalid TCP/UDP checksum
time=1970-01-01T00:10:35.908Z level=ERROR msg=Stack.RecvEth err="invalid TCP/UDP checksum"
time=1970-01-01T00:10:35.909Z level=ERROR msg=tryPoll:rx plen=0 err="invalid TCP/UDP checksum"
poll error: invalid TCP/UDP checksum
time=1970-01-01T00:10:40.505Z level=ERROR msg=Stack.RecvEth err="invalid TCP/UDP checksum"
time=1970-01-01T00:10:40.506Z level=ERROR msg=tryPoll:rx plen=0 err="invalid TCP/UDP checksum"
poll error: invalid TCP/UDP checksum
time=1970-01-01T00:10:49.391Z level=ERROR msg=Stack.RecvEth err="invalid TCP/UDP checksum"
time=1970-01-01T00:10:49.392Z level=ERROR msg=tryPoll:rx plen=0 err="invalid TCP/UDP checksum"
poll error: invalid TCP/UDP checksum
time=1970-01-01T00:11:07.315Z level=ERROR msg=Stack.RecvEth err="invalid TCP/UDP checksum"
time=1970-01-01T00:11:07.316Z level=ERROR msg=tryPoll:rx plen=0 err="invalid TCP/UDP checksum"
poll error: invalid TCP/UDP checksum
time=1970-01-01T00:11:44.285Z level=ERROR msg=Stack.RecvEth err="invalid TCP/UDP checksum"
time=1970-01-01T00:11:44.286Z level=ERROR msg=tryPoll:rx plen=0 err="invalid TCP/UDP checksum"
poll error: invalid TCP/UDP checksum
scottfeldman commented 10 months ago

I have a pcap file captured on the client side I'll attach.

scottfeldman commented 10 months ago

test.zip

soypat commented 10 months ago

So it seems like packet number 3651 is the problematic packet. Will add a test later this week and see if I catch anything. Leaving the packet here as a hexdump:

0000   28 cd c1 01 13 7c 88 ae dd 0a 70 92 08 00 45 00
0010   00 2d b0 3a 40 00 40 06 75 59 0a 00 00 be 0a 00
0020   00 7a c7 ce 04 d2 2a 67 58 17 00 00 0d 53 50 18
0030   fa 4b ff ff 00 00 68 65 6c 6c 6f
soypat commented 10 months ago

I've added a failing test for this in seqs: https://github.com/soypat/seqs/blob/42f969a224f4707ac986bc4882fac74509a7f0fb/stacks/stacks_test.go#L366

soypat commented 10 months ago

@scottfeldman It seems like the mistake is on the client's side, not seqs according to all online packet analyzers I've tried and wireshark.

image

scottfeldman commented 10 months ago

I don't think the client is making a mistake. Wireshark can't see the final csum because the tcp csum is offloaded to the hw NIC on the client side at 10.0.0.190.

sfeldma@nuc:~$ ip a show dev eno1
2: eno1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default qlen 1000
    link/ether 88:ae:dd:0a:70:92 brd ff:ff:ff:ff:ff:ff
    altname enp2s0
    inet 10.0.0.190/24 brd 10.0.0.255 scope global dynamic noprefixroute eno1
       valid_lft 4578sec preferred_lft 4578sec
    inet6 fe80::59c6:7ccb:127b:5b75/64 scope link noprefixroute 
       valid_lft forever preferred_lft forever
sfeldma@nuc:~$ sudo ethtool -k eno1 | head -n20
Features for eno1:
rx-checksumming: on
tx-checksumming: on
        tx-checksum-ipv4: on                         <<<<<<<<<<<<<<<<< right here
        tx-checksum-ip-generic: off [fixed]
        tx-checksum-ipv6: on
        tx-checksum-fcoe-crc: off [fixed]
        tx-checksum-sctp: off [fixed]
scatter-gather: off
        tx-scatter-gather: off
        tx-scatter-gather-fraglist: off [fixed]
tcp-segmentation-offload: off
        tx-tcp-segmentation: off
        tx-tcp-ecn-segmentation: off [fixed]
        tx-tcp-mangleid-segmentation: off
        tx-tcp6-segmentation: off
generic-segmentation-offload: off [requested on]
generic-receive-offload: on
large-receive-offload: off [fixed]
rx-vlan-offload: on
soypat commented 10 months ago

OK, so taking a closer look the first TCP checksum error occurs at timestamp=10:31.560Z, which occurs 10 minutes 24 seconds after the DHCP exchange (624s) which corresponds to wireshark timestamp 624-20=604s- there's not much happening at that point- connection proceeds normally up to the 644s wireshark timestamp, where the client's messages stop being acknowledged by the server.

Interestingly, up to this point all previous checksums are correct as marked by Wireshark- which seems to indicate the TCP checksum is not being offloaded. The packet which fails to be acked by the seqs server has the checksum=0xffff. Wireshark tells us that the correct checksum is 0. image

I've added a test for this package in seqs which does yield the correct checksum.

If the issue is seqs for the program above then it would seem I'm looking at an incorrect packet in the stream- but I can't seem to find any other anomaly in between packets other than the mentioned packet.

also, tx-checksum-ipv4: on sounds like it may pertain to the IP header checksum, not the TCP checksum.

scottfeldman commented 10 months ago

Oh, interesting. I'm not sure what's going on then.

Let's keep this one open for awhile in case it pops up again.

soypat commented 7 months ago

Final period for comments before closing!