VPN connection loss on MacOS

Tue Nov 26 17:44:25 UTC 2024

Hello,

At $WORK we have noticed that Wireguard on MacOS occasionally stops 
sending outbound traffic. From users' perspective it just freezes and 
disconnecting and reconnecting solves the issue.

 From sysadmin perspective the cloned route (the one shown with netstat 
-nral) bound to the interface disappears and normal route lookup takes 
over, which overlaps with tunneled routes. We have multiple IPv4 and a 
few IPv6 prefixes configuerd as AllowedIPs and the VPN server is hosted 
within those prefixes. Or in case of my own experiment today the cloned 
route points to the tunnel itself.

I suspect the issue happens when users switch between WiFi networks or 
between WiFi and LAN.

I've tried to reproduce it on my own MacBook and so far I've came up 
with being able to force Wireguard to stick to binding to its own 
interface by disabling WiFi, using only LAN, and then disconnecting the 
docking station, which causes the LAN interface to disappear.

Log:

WiFi is disabled, the only available interface is LAN via a docking station.

2024-11-26 17:48:27.384678: [APP] startActivation: Entering (tunnel: 
IG-Secondary_01)
2024-11-26 17:48:27.387304: [APP] startActivation: Starting tunnel
2024-11-26 17:48:27.387545: [APP] startActivation: Success
2024-11-26 17:48:27.394164: [APP] Tunnel 'IG-Secondary_01' connection 
status changed to 'connecting'
2024-11-26 17:48:27.634612: [NET] App version: 1.0.16 (27)
2024-11-26 17:48:27.634679: [NET] Starting tunnel from the app
2024-11-26 17:48:27.862822: [NET] DNS64: mapped XXX.XXX.XXX.XXX to itself.
2024-11-26 17:48:27.863793: [NET] Attaching to interface
2024-11-26 17:48:27.864087: [NET] UAPI: Updating private key
2024-11-26 17:48:27.864280: [NET] UAPI: Removing all peers
2024-11-26 17:48:27.864497: [NET] peer(/1jY…HEkg) - UAPI: Created
2024-11-26 17:48:27.864544: [NET] peer(/1jY…HEkg) - UAPI: Updating 
preshared key
2024-11-26 17:48:27.864589: [NET] peer(/1jY…HEkg) - UAPI: Updating endpoint
2024-11-26 17:48:27.864637: [NET] peer(/1jY…HEkg) - UAPI: Updating 
persistent keepalive interval
2024-11-26 17:48:27.864731: [NET] peer(/1jY…HEkg) - UAPI: Removing all 
allowedips
2024-11-26 17:48:27.864774: [NET] peer(/1jY…HEkg) - UAPI: Adding allowedip
2024-11-26 17:48:27.864845: [NET] peer(/1jY…HEkg) - UAPI: Adding allowedip
2024-11-26 17:48:27.864913: [NET] peer(/1jY…HEkg) - UAPI: Adding allowedip
2024-11-26 17:48:27.864983: [NET] peer(/1jY…HEkg) - UAPI: Adding allowedip
2024-11-26 17:48:27.865022: [NET] peer(/1jY…HEkg) - UAPI: Adding allowedip
2024-11-26 17:48:27.865089: [NET] peer(/1jY…HEkg) - UAPI: Adding allowedip
2024-11-26 17:48:27.865100: [NET] Routine: encryption worker 5 - started
2024-11-26 17:48:27.865157: [NET] peer(/1jY…HEkg) - UAPI: Adding allowedip
2024-11-26 17:48:27.865231: [NET] Routine: encryption worker 2 - started
2024-11-26 17:48:27.865255: [NET] peer(/1jY…HEkg) - UAPI: Adding allowedip
2024-11-26 17:48:27.865321: [NET] peer(/1jY…HEkg) - UAPI: Adding allowedip
2024-11-26 17:48:27.865422: [NET] peer(/1jY…HEkg) - UAPI: Adding allowedip
2024-11-26 17:48:27.865472: [NET] peer(/1jY…HEkg) - UAPI: Adding allowedip
2024-11-26 17:48:27.865510: [NET] peer(/1jY…HEkg) - UAPI: Adding allowedip
2024-11-26 17:48:27.865695: [NET] Routine: encryption worker 8 - started
2024-11-26 17:48:27.865780: [NET] Routine: decryption worker 5 - started
2024-11-26 17:48:27.865836: [NET] Routine: handshake worker 5 - started
2024-11-26 17:48:27.865870: [NET] UDP bind has been updated
2024-11-26 17:48:27.865896: [NET] Routine: encryption worker 6 - started
2024-11-26 17:48:27.865938: [NET] peer(/1jY…HEkg) - Starting
2024-11-26 17:48:27.865957: [NET] Routine: decryption worker 6 - started
2024-11-26 17:48:27.866008: [NET] Routine: handshake worker 6 - started
2024-11-26 17:48:27.866046: [NET] Routine: encryption worker 1 - started
2024-11-26 17:48:27.866108: [NET] peer(/1jY…HEkg) - Sending keepalive packet
2024-11-26 17:48:27.866141: [NET] Routine: decryption worker 1 - started
2024-11-26 17:48:27.866185: [NET] Routine: handshake worker 1 - started
2024-11-26 17:48:27.866265: [NET] peer(/1jY…HEkg) - Sending handshake 
initiation
2024-11-26 17:48:27.867954: [NET] Interface state was Down, requested 
Up, now Up
2024-11-26 17:48:27.867999: [NET] Routine: decryption worker 2 - started
2024-11-26 17:48:27.868151: [NET] Device started
2024-11-26 17:48:27.868328: [NET] Tunnel interface is utun7
2024-11-26 17:48:27.868422: [NET] Routine: decryption worker 7 - started
2024-11-26 17:48:27.868471: [NET] Routine: decryption worker 10 - started
2024-11-26 17:48:27.868485: [NET] Routine: encryption worker 7 - started
2024-11-26 17:48:27.868530: [NET] Routine: encryption worker 9 - started
2024-11-26 17:48:27.868571: [NET] Routine: handshake worker 7 - started
2024-11-26 17:48:27.868575: [NET] Routine: decryption worker 9 - started
2024-11-26 17:48:27.868603: [NET] Network change detected with satisfied 
route and interface order [en4]
2024-11-26 17:48:27.868806: [NET] Routine: handshake worker 3 - started
2024-11-26 17:48:27.868838: [NET] Routine: encryption worker 4 - started
2024-11-26 17:48:27.868862: [NET] Routine: handshake worker 2 - started
2024-11-26 17:48:27.869054: [APP] Tunnel 'IG-Secondary_01' connection 
status changed to 'connected'
2024-11-26 17:48:27.872242: [NET] Routine: encryption worker 3 - started
2024-11-26 17:48:27.872367: [NET] Routine: decryption worker 8 - started
2024-11-26 17:48:27.872365: [NET] Routine: handshake worker 9 - started
2024-11-26 17:48:27.872380: [NET] Routine: receive incoming v4 - started
2024-11-26 17:48:27.872387: [NET] Routine: handshake worker 8 - started
2024-11-26 17:48:27.872409: [NET] Routine: decryption worker 4 - started
2024-11-26 17:48:27.872458: [NET] Routine: encryption worker 10 - started
2024-11-26 17:48:27.872428: [NET] peer(/1jY…HEkg) - Routine: sequential 
sender - started
2024-11-26 17:48:27.872483: [NET] Routine: handshake worker 4 - started
2024-11-26 17:48:27.872491: [NET] Routine: handshake worker 10 - started
2024-11-26 17:48:27.872504: [NET] Routine: decryption worker 3 - started
2024-11-26 17:48:27.872587: [NET] Routine: event worker - started
2024-11-26 17:48:27.872587: [NET] Routine: receive incoming v6 - started
2024-11-26 17:48:27.872619: [NET] peer(/1jY…HEkg) - Routine: sequential 
receiver - started
2024-11-26 17:48:27.872743: [NET] Routine: TUN reader - started
2024-11-26 17:48:27.872741: [NET] Routine: receive incoming v4 - stopped
2024-11-26 17:48:27.872835: [NET] Routine: receive incoming v6 - stopped
2024-11-26 17:48:27.872873: [NET] peer(/1jY…HEkg) - Received handshake 
response
2024-11-26 17:48:27.873074: [NET] Routine: receive incoming v4 - started
2024-11-26 17:48:27.873085: [NET] Routine: receive incoming v6 - started
2024-11-26 17:48:27.873093: [NET] UDP bind has been updated
2024-11-26 17:48:27.873182: [NET] peer(/1jY…HEkg) - Sending keepalive packet
2024-11-26 17:48:27.876862: [NET] peer(/1jY…HEkg) - Receiving keepalive 
packet
2024-11-26 17:48:27.941593: [NET] Network change detected with satisfied 
route and interface order [en4, utun7]
2024-11-26 17:48:27.957116: [NET] Routine: receive incoming v4 - stopped
2024-11-26 17:48:27.957351: [NET] Routine: receive incoming v6 - stopped
2024-11-26 17:48:27.957570: [NET] UDP bind has been updated
2024-11-26 17:48:27.957630: [NET] peer(/1jY…HEkg) - Sending keepalive packet
2024-11-26 17:48:27.957706: [NET] Routine: receive incoming v4 - started
2024-11-26 17:48:27.957769: [NET] Routine: receive incoming v6 - started
2024-11-26 17:48:32.387902: [APP] Status update notification timeout for 
tunnel 'IG-Secondary_01'. Tunnel status is now 'connected'.

Docking station is disconnected, en4 is gone.

2024-11-26 17:49:05.081342: [NET] peer(/1jY…HEkg) - Failed to send data 
packet: write udp4 0.0.0.0:50737->XXX.XXX.XXX.XXX:51820: sendto: network 
is unreachable
2024-11-26 17:49:05.213864: [NET] Network change detected with 
unsatisfied route and interface order [utun7]
2024-11-26 17:49:05.264385: [NET] Routine: receive incoming v6 - stopped
2024-11-26 17:49:05.263265: [NET] Routine: receive incoming v4 - stopped
2024-11-26 17:49:05.268465: [NET] UDP bind has been updated
2024-11-26 17:49:05.268545: [NET] peer(/1jY…HEkg) - Sending keepalive packet
2024-11-26 17:49:05.268850: [NET] Routine: receive incoming v4 - started
2024-11-26 17:49:05.269030: [NET] Routine: receive incoming v6 - started
2024-11-26 17:49:05.306968: [NET] Network change detected with 
unsatisfied route and interface order [utun7]
2024-11-26 17:49:05.309730: [NET] Routine: receive incoming v4 - stopped
2024-11-26 17:49:05.309761: [NET] Routine: receive incoming v6 - stopped
2024-11-26 17:49:05.310009: [NET] UDP bind has been updated
2024-11-26 17:49:05.310041: [NET] peer(/1jY…HEkg) - Sending keepalive packet
2024-11-26 17:49:05.310623: [NET] Routine: receive incoming v4 - started
2024-11-26 17:49:05.310692: [NET] Routine: receive incoming v6 - started
2024-11-26 17:49:05.560498: [NET] Network change detected with 
unsatisfied route and interface order [utun7]
2024-11-26 17:49:15.312034: [NET] peer(/1jY…HEkg) - Sending keepalive packet
2024-11-26 17:49:20.267118: [NET] peer(/1jY…HEkg) - Retrying handshake 
because we stopped hearing back after 15 seconds
2024-11-26 17:50:43.393276: [NET] peer(/1jY…HEkg) - Sending keepalive packet

Docking station is plugged in again, no change. Wifi gets enabled, no 
change either. utun7 is the last seen interface. The bound socket can be 
seen from command line:

[17:49:48] MB-20001482 ndco-scripts/ # netstat -nr | grep -E 
'XXX\.XXX.XXX\.XXX'
XXX.XXX.XXX.XXX       link#29            UHWIi               utun7

-- 
| pozdrawiam / regards | Powered by macOS, Debian and FreeBSD |
| Kajetan Staszkiewicz |  www: http://vegeta.tuxpowered.net   |
`----------------------^--------------------------------------'

-------------- next part --------------
A non-text attachment was scrubbed...
Name: OpenPGP_signature.asc
Type: application/pgp-signature
Size: 840 bytes
Desc: OpenPGP digital signature
URL: <http://lists.zx2c4.com/pipermail/wireguard/attachments/20241126/dc2b4f7d/attachment.sig>