sendmmsg: message too long

[wizzardich]

Hello!

I suddenly started running into an issue with swgp-go 1.8. My previous installation was running 1.6 without much problems, but after recent update something started going wrong. At this moment I cannot reliably even establish the connection, I keep recieveing:

Oct 26 22:14:19.968 WRN Failed to write swgpPacket to proxyConn client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:34380 proxyConnListenAddress=<local_ip>:47191 proxyAddress=<server_ip>:20220 swgpPacketLength=1376 err="sendmmsg: message too long"
Oct 26 22:14:19.970 WRN Failed to write swgpPacket to proxyConn client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:34380 proxyConnListenAddress=<local_ip>:47191 proxyAddress=<server_ip>:20220 swgpPacketLength=1376 err="sendmmsg: message too long"
Oct 26 22:14:20.021 WRN Failed to write swgpPacket to proxyConn client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:34380 proxyConnListenAddress=<local_ip>:47191 proxyAddress=<server_ip>:20220 swgpPacketLength=1360 err="sendmmsg: message too long"
Oct 26 22:14:20.052 WRN Failed to write swgpPacket to proxyConn client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:34380 proxyConnListenAddress=<local_ip>:47191 proxyAddress=<server_ip>:20220 swgpPacketLength=2752 err="sendmmsg: message too long"

The MTUs are set as recommended. I tried enabling / disabling UDP GSO as well, but to no avail. Moreover, I'm sure that in-between the connection allows for MTU of 1500:

➜ ping server -s 1472 -M do
PING server (<server_ip>) 1472(1500) bytes of data.
1480 bytes from <server_ip>: icmp_seq=1 ttl=53 time=123 ms
1480 bytes from <server_ip>: icmp_seq=2 ttl=53 time=123 ms
^C
--- server ping statistics ---
2 packets transmitted, 2 received, 0% packet loss, time 1000ms
rtt min/avg/max/mdev = 122.553/122.591/122.629/0.038 ms

[22:15:42] ~ 
➜ ping server -s 1473 -M do
PING server (<server_ip>) 1473(1501) bytes of data.
ping: sendmsg: Message too long
^C
--- server ping statistics ---
1 packets transmitted, 0 received, +1 errors, 100% packet loss, time 0ms

I'm not sure if this is a problem with my config still. Any help would be appreciated.

Logs

Oct 26 21:56:04.829 INF swgp-go version=1.8.0
Oct 26 21:56:04.832 INF Started service client=client listenAddress=[::]:20222 proxyAddress=<server_ip>:20220 wgTunnelMTU=1360 maxUDPGSOSegments=64 udpGRO=true
Oct 26 21:56:13.474 DBG Updated client pktinfo client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:45294 clientPktinfoAddr=::ffff:127.0.0.1 clientPktinfoIfindex=1
Oct 26 21:56:13.474 DBG New client session client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:45294 proxyAddress=<server_ip>:20220
Oct 26 21:56:13.474 INF Client relay started client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:45294 proxyConnListenAddress=<local_ip>:44490 proxyAddress=<server_ip>:20220 wgTunnelMTU=1360 maxUDPGSOSegments=1 udpGRO=true
Oct 26 21:56:26.649 DBG Updated client pktinfo client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:57826 clientPktinfoAddr=::ffff:127.0.0.1 clientPktinfoIfindex=1
Oct 26 21:56:26.649 DBG New client session client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:57826 proxyAddress=<server_ip>:20220
Oct 26 21:56:26.650 INF Client relay started client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:57826 proxyConnListenAddress=<local_ip>:42935 proxyAddress=<server_ip>:20220 wgTunnelMTU=1360 maxUDPGSOSegments=1 udpGRO=true
Oct 26 21:56:26.782 WRN Failed to write swgpPacket to proxyConn client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:57826 proxyConnListenAddress=<local_ip>:42935 proxyAddress=<server_ip>:20220 swgpPacketLength=1392 err="sendmmsg: message too long"
Oct 26 21:56:29.523 WRN Failed to write swgpPacket to proxyConn client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:57826 proxyConnListenAddress=<local_ip>:42935 proxyAddress=<server_ip>:20220 swgpPacketLength=1344 err="sendmmsg: message too long"
Oct 26 21:59:13.476 INF Finished relay proxyConn -> wgConn client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:45294 proxyConnListenAddress=<local_ip>:44490 proxyAddress=<server_ip>:20220 recvmmmsgCount=1 msgsReceived=1 packetsReceived=1 swgpBytesReceived=604 sendmmsgCount=1 msgsSent=1 packetsSent=1 wgBytesSent=92 burstRecvBatchSize=1 burstSendBatchSize=1 burstRecvSegmentCount=1 burstSendSegmentCount=1
Oct 26 21:59:13.476 INF Finished relay wgConn -> proxyConn client=client listenAddress=[::]:20222 clientAddress=[::ffff:127.0.0.1]:45294 proxyConnListenAddress=<local_ip>:44490 proxyAddress=<server_ip>:20220 sendmmsgCount=1 msgsSent=1 packetsSent=1 swgpBytesSent=966 burstBatchSize=1 burstSegmentCount=1

Configs

1. Client swgp-go/config.json

   {
       "clients": [
           {
               "name": "client",
               "wgListen": ":20222",
               "proxyEndpoint": "<server IP>:20220",
               "proxyMode": "zero-overhead",
               "proxyPSK": "...",
               "mtu": 1424
           }
       ]
   }

2. Client wg.conf

   [Interface]
   PrivateKey = ...
   Address = 10.42.0.3/24
   DNS = 208.67.222.222
   MTU = 1360
   
   [Peer]
   PublicKey = ...
   PresharedKey = ...
   AllowedIPs = 0.0.0.0/0
   Endpoint = 127.0.0.1:20222
   PersistentKeepalive = 15

3. Server swgp-go/config.json

   {
       "servers": [
           {
               "name": "wg-proxy",
               "proxyListen": ":20220",
               "proxyMode": "zero-overhead",
               "proxyPSK": "...",
               "wgEndpoint": "127.0.0.1:51820",
               "mtu": 1424
           }
       ]
   }

4. Server wg.conf

   [Interface]
   Address = 10.42.0.1/24
   MTU = 1360
   ...
   ListenPort = 51820
   PrivateKey = ...
   
   [Peer]
   PublicKey = ...
   PresharedKey = ...
   AllowedIPs = 10.42.0.3/32

[database64128]

I'm sure that in-between the connection allows for MTU of 1500

ICMP packets may not end up on the same network path as UDP packets. Can you use WireShark or tcpdump to capture with filter udp port 20222 or icmp (Based on the MTU values in the logs I'm assuming IPv4) to see the exact ICMP packet that's triggering the "message too long" error?

Client swgp-go/config.json

Can you try adding "disableMmsg": true to your client config? One of the significant changes in v1.8.0 is that the mmsg path now uses connect(2). I wonder if this is somehow causing the problem here.

[wizzardich]

Please be more specific. What MTU values did you try? Did you modify the MTU option of swgp-go client, server, and client wg.conf simultaneously?

I honestly don't see much of a point of doing it separately. Both sides of the connection, tried values ranging from 512 to 1492, kept the advised values of swgp-go startup as values set for WG configs. It's a tedious process, but I am doing this on both client and server, though packets never actually leave client so far.

Specifically, tried MTU settings:

• 1360 on wg, 1424 on swgp
• 1216 on wg, 1280 on swgp
• 512 on wg, 1280 on swgp

I tried other combinations as well, these are just the latest.

lo's MTU doesn't matter.

It does matter on the connection to swgp-go client, correct? That's what I was aiming to exclude.

Not sure what you did, but the timestamps don't match. Please use the filter I mentioned in my earlier comment, so that ICMP packets are included.

I only had one instance of tcpdump operating, so I restarted wg several times. I'll add the specific simultaneous pcap below.
What I did to get traffic on pcap (this is not ping based now, just organic traffic):

[21:13:01] ~ 
➜ wg-quick up wg1
[#] ip link add dev wg1 type wireguard
[#] wg setconf wg1 /dev/fd/63
[#] ip -4 address add 10.42.0.3/24 dev wg1
[#] ip link set mtu 1360 up dev wg1
[#] resolvconf -a wg1 -m 0 -x
[#] wg set wg1 fwmark 51820
[#] ip -4 rule add not fwmark 51820 table 51820
[#] ip -4 rule add table main suppress_prefixlength 0
[#] ip -4 route add 0.0.0.0/0 dev wg1 table 51820
[#] sysctl -q net.ipv4.conf.all.src_valid_mark=1
[#] iptables-restore -n
[21:13:12] ~ 
➜ wg-quick down wg1
[#] ip -4 rule delete table 51820
[#] ip -4 rule delete table main suppress_prefixlength 0
[#] ip link delete dev wg1
[#] resolvconf -d wg1 -f
[#] iptables-restore -n

MTU set to 1360 on wg, 1424 on swgp

1. swgp-client -> swgp-server (filtering for swgp server port, monitoring my wired interface):

   [21:13:03] ~ took 2m55s 
   ➜ sudo tcpdump -nvvi enp0s31f6 dst port 20220 or src port 20220
   tcpdump: listening on enp0s31f6, link-type EN10MB (Ethernet), snapshot length 262144 bytes
   21:13:12.251246 IP (tos 0x0, ttl 64, id 2782, offset 0, flags [DF], proto UDP (17), length 630)
       192.168.88.10.55243 > <server ip>.20220: [bad udp cksum 0x970b -> 0x35b0!] UDP, length 602
   21:13:12.378759 IP (tos 0x0, ttl 53, id 0, offset 0, flags [DF], proto UDP (17), length 270)
       <server ip>.20220 > 192.168.88.10.55243: [udp sum ok] UDP, length 242
   ^C
   2 packets captured
   2 packets received by filter
   0 packets dropped by kernel
   [21:13:41] ~ took 33s

2. wg -> swgp-client (filtering for swgp client port, monitoring lo, because that's where server is bound):

   [21:13:04] ~ took 3m1s 
   ➜ sudo tcpdump -nvvi lo dst port 20222 or src port 20222
   tcpdump: listening on lo, link-type EN10MB (Ethernet), snapshot length 262144 bytes
   21:13:12.250378 IP (tos 0x88, ttl 64, id 62650, offset 0, flags [none], proto UDP (17), length 176)
       127.0.0.1.50265 > 127.0.0.1.20222: [bad udp cksum 0xfeaf -> 0x5c50!] UDP, length 148
   ...
   ...
   ...
   21:13:13.875236 IP (tos 0x0, ttl 64, id 63847, offset 0, flags [none], proto UDP (17), length 1308)
       127.0.0.1.50265 > 127.0.0.1.20222: [bad udp cksum 0x031c -> 0x4e4e!] UDP, length 1280
   21:13:13.875263 IP (tos 0x0, ttl 64, id 63848, offset 0, flags [none], proto UDP (17), length 1372)
       127.0.0.1.50265 > 127.0.0.1.20222: [bad udp cksum 0x035c -> 0x1b04!] UDP, length 1344
   ^C
   523 packets captured
   1046 packets received by filter
   0 packets dropped by kernel
   [21:13:39] ~ took 34s 

---

MTU set to 512 on wg, 1280 on swgp

1. swgp-client -> swgp-server (filtering for swgp server port, monitoring my wired interface):

   ➜ sudo tcpdump -nvvi enp0s31f6 dst port 20220 or src port 20220
   tcpdump: listening on enp0s31f6, link-type EN10MB (Ethernet), snapshot length 262144 bytes
   21:29:35.604766 IP (tos 0x0, ttl 64, id 64996, offset 0, flags [DF], proto UDP (17), length 583)
       192.168.88.10.52012 > 172.104.207.124.20220: [bad udp cksum 0x96dc -> 0x3b99!] UDP, length 555
   21:29:35.724476 IP (tos 0x0, ttl 53, id 0, offset 0, flags [DF], proto UDP (17), length 572)
       172.104.207.124.20220 > 192.168.88.10.52012: [udp sum ok] UDP, length 544
   ^C
   2 packets captured
   2 packets received by filter
   0 packets dropped by kernel
   [21:30:09] ~ took 39s
   

2. swgp-client -> swgp-server (filtering for swgp server port, monitoring my wired interface):

   ➜ sudo tcpdump -nvvi lo dst port 20222 or src port 20222
   tcpdump: listening on lo, link-type EN10MB (Ethernet), snapshot length 262144 bytes
   21:29:35.604358 IP (tos 0x88, ttl 64, id 40338, offset 0, flags [none], proto UDP (17), length 176)
       127.0.0.1.48559 > 127.0.0.1.20222: [bad udp cksum 0xfeaf -> 0x3840!] UDP, length 148
   21:29:35.724652 IP (tos 0x0, ttl 64, id 0, offset 0, flags [DF], proto UDP (17), length 120)
       127.0.0.1.20222 > 127.0.0.1.48559: [bad udp cksum 0xfe77 -> 0x908f!] UDP, length 92
   21:29:35.724745 IP (tos 0x0, ttl 64, id 40361, offset 0, flags [none], proto UDP (17), length 60)
       127.0.0.1.48559 > 127.0.0.1.20222: [bad udp cksum 0xfe3b -> 0x08a0!] UDP, length 32
   ...
   ...
   ...
   21:29:36.816542 IP (tos 0x0, ttl 64, id 41409, offset 0, flags [none], proto UDP (17), length 492)
       127.0.0.1.48559 > 127.0.0.1.20222: [bad udp cksum 0xffeb -> 0xb168!] UDP, length 464
   21:29:36.816555 IP (tos 0x0, ttl 64, id 41410, offset 0, flags [none], proto UDP (17), length 508)
       127.0.0.1.48559 > 127.0.0.1.20222: [bad udp cksum 0xfffb -> 0x844e!] UDP, length 480
   21:29:36.816593 IP (tos 0x0, ttl 64, id 41411, offset 0, flags [none], proto UDP (17), length 556)
       127.0.0.1.48559 > 127.0.0.1.20222: [bad udp cksum 0x002c -> 0xb2ef!] UDP, length 528
   21:29:36.816595 IP (tos 0x0, ttl 64, id 41412, offset 0, flags [none], proto UDP (17), length 572)
   ...
   ...
   ...
   21:29:37.024549 IP (tos 0x0, ttl 64, id 41603, offset 0, flags [none], proto UDP (17), length 556)
       127.0.0.1.48559 > 127.0.0.1.20222: [bad udp cksum 0x002c -> 0xdbe1!] UDP, length 528
   ^C
   143 packets captured
   286 packets received by filter
   0 packets dropped by kernel
   

[database64128]

I honestly don't see much of a point of doing it separately.

And I never asked you to! I was just asking about what you did, since your description was rather vague.

It does matter on the connection to swgp-go client, correct?

No, we do not care about lo's MTU anywhere at all.

packets never actually leave client so far

Packets won't just disappear inside swgp-go's pipeline. If a packet was dropped, there would be a warning log message.

Your tcpdump output shows that no further packets from the swgp-go client were sent on the link after the handshake. This could mean either sending failed or something else went wrong. Can you please attach the associated swgp-go logs, and do as I asked in my earlier comments to include ICMP packets in the capture filter:

Can you use WireShark or tcpdump to capture with filter udp port 20222 or icmp (Based on the MTU values in the logs I'm assuming IPv4) to see the exact ICMP packet that's triggering the "message too long" error?

Please use the filter I mentioned in my earlier comment, so that ICMP packets are included.

Trust me, I want to get to the bottom of this just as much as you do! But there's nothing I can do, if you don't provide the necessary information for me to understand the problem. Thanks!

[wizzardich]

No worries, and apologies for vague explanations! I'm prone to skipping some context that exists in my head, I guess ^^"

Attaching logs as files, as there's quite a lot of them. FWIW, I never though packets disappear, I think they do get discarded with the sendmmsg: message too long error log. I just can't understand why it is so...

I ran two tests: one with larger ping packets (1500 total bytes), another with normal ping packets (64 bytes).

1. ping.log - 1500 byte packets, clearly run into MTU issue due to MTU being set to 512 since yesterday's tests once WG is enabled.
2. ping-no-size.log - 64 byte packets, once WG is enabled these never register neither in ping output, nor in tcpdump.
3. swgp-go.log - full swgp-go log for the duration of the tests.
4. tcpdump.log - tcpdump for the first ping test with large packets.
5. tcpdump-no-size.log - tcpdump for the second ping test with normal packets. Neither registered the ICMP packets while WG was up (and routing active).
6. wg-timeline.log - timeline of WG activation/deactivation for cross-reference.

[database64128]

Neither registered the ICMP packets while WG was up (and routing active).

Looks like I wrote the wrong port number in my earlier comments, sorry! The swgp-go server port is 20220, so you need to capture on enp0s31f6 with udp port 20220 or icmp.

There's no need to ping the server yourself. What I want to see is ICMP packets sent from the middle boxes, not from your systems. Just run tcpdump, start the swgp-go client, observe sendmmsg: message too long, and that's it. Attach the client log and tcpdump output.

[database64128]

Not sure if you are still seeing this problem. I just added support for configuring to use other PMTUD modes in ace20b3. You can try "pathMTUDiscovery": "interface".