search

eduvpn / apple

app for iOS and macOS
Other
55 stars 19 forks source link

WireGuard fails after suspend #527

Open efef opened 8 months ago

efef commented 8 months ago

After suspend, sometimes WireGuard isn't reconnecting. In log-file is shown:

2023-09-18 08:45:06.473 peer(NKrI…arBc) - Sending handshake initiation
2023-09-18 08:45:06.473 peer(NKrI…arBc) - Failed to send handshake initiation: write udp4 0.0.0.0:62164->145.100.179.27:443: sendto: no route to host
2023-09-18 08:45:11.476 peer(NKrI…arBc) - Sending handshake initiation
2023-09-18 08:45:11.477 peer(NKrI…arBc) - Failed to send handshake initiation: write udp4 0.0.0.0:62164->145.100.179.27:443: sendto: no route to host

other example

2023-10-17 12:34:02.089014: [NET] peer(xxEb\'85+tms) - Failed to send handshake initiation: write udp4 0.0.0.0:53609->145.220.52.76:443: sendto: operation not permitted\
2023-10-17 12:34:07.280567: [NET] peer(xxEb\'85+tms) - Handshake did not complete after 5 seconds, retrying (try 2)\
2023-10-17 12:34:07.281117: [NET] peer(xxEb\'85+tms) - Sending handshake initiation\
2023-10-17 12:34:07.282677: [NET] peer(xxEb\'85+tms) - Failed to send handshake initiation: write udp4 0.0.0.0:53609->145.220.52.76:443: sendto: operation not permitted\
2023-10-17 12:34:12.493827: [NET] peer(xxEb\'85+tms) - Sending handshake initiation\

Somehow on my own Mac I can't trigger this issue, but on another Mac it is trivial to get this issue. It can also be triggered by turn on/off/on/off/on VPN, meanwhile "ping 8.8.8.8" and wait untill all ping-reply fails when VPN was turned "on".

On my own macbook I can trigger a comparable isssue by actively blocking the tunnel extension: "/usr/libexec/ApplicationFirewall/socketfilterfw --blockapp /Applications/eduVPN.app/Contents/PlugIns/TunnelExtension-macOS.appex" When it is blocked, sometimes WireGuard works, but sometimes the firewall blocks the traffic.

The issue is also found when using latest WireGuard app from Appstore

Sometimes the VPN recovers after for example 10 minutes when "suddenly" a network change was detected. This example is from WireGuard log:

[NET] Network change detected with satisfied route and interface order [en6, utun3]\

efef commented 8 months ago

testing this issue when turn off/on/off/on untill it happens: https://github.com/eduvpn/apple/assets/3393474/22fbf870-b864-4e4b-b8c7-ea9c5a498407

To 'solve' the issue a user could disconnect VPN (and reconnect) or turn off/on WiFi https://github.com/eduvpn/apple/assets/3393474/0299ff2b-5ea8-44bc-8e88-3e6a8be8c074

efef commented 8 months ago

this issue seems related: https://www.reddit.com/r/WireGuard/comments/105l3bb/comment/jix8fkp/?utm_source=reddit&utm_medium=web2x&context=3

When testing with WireGuard I notice when internet isn't working there is a wrong route with VPN server over tunnel interface set.

Ebrink commented 2 months ago

I am able to reproduce this issue consistently using the following steps:

  • Start with WG tunnel in an operational state
  • Disconnect network (e.g. if on WiFI, turn off the WiFi in the menu bar)
  • Sleep the machine
  • Wait- Wake the machine
  • Turn on Wifi
  • Note that WG client fails to re-establish connectivity (shows connected, but no traffic flows until you deactivate/reactivate WG)

(found in this mail thread: https://lore.kernel.org/wireguard/CAHmME9qomaQdNUsvhDtp2caxAGBGXLee5FT_C8_q9A=yzQP3iA@mail.gmail.com/T/)

Issue does not appear when running an EduVPN profile in PassePartout (2.3.5 (3599)).

Issue can also be reproduced with the native Wireguard app (version 1.0.16 (27)). Also: issue only surfaces on my Mac when it is connected to power.

Logging for the tunnel on EduVPN app:

2024-04-16 07:49:23.505 peer(NKrI…arBc) - Failed to send data packet: write udp4 0.0.0.0:60617->145.x.x.x:51820: sendto: network is unreachable
2024-04-16 07:49:23.508 peer(NKrI…arBc) - Failed to send data packet: write udp4 0.0.0.0:60617->145.x.x.x:51820: sendto: network is unreachable
2024-04-16 07:49:23.519 peer(NKrI…arBc) - Failed to send data packet: write udp4 0.0.0.0:60617->145.x.x.x:51820: sendto: network is unreachable
2024-04-16 07:49:23.550 Network change detected with unsatisfied route and interface order [en0, utun9]
2024-04-16 07:49:23.553 Routine: receive incoming v4 - stopped
2024-04-16 07:49:23.553 Routine: receive incoming v6 - stopped
2024-04-16 07:49:23.553 UDP bind has been updated
2024-04-16 07:49:23.553 peer(NKrI…arBc) - Sending keepalive packet
2024-04-16 07:49:23.553 Routine: receive incoming v4 - started
2024-04-16 07:49:23.553 Routine: receive incoming v6 - started
2024-04-16 07:49:23.660 Network change detected with unsatisfied route and interface order [utun9]
2024-04-16 07:49:26.168 peer(NKrI…arBc) - Retrying handshake because we stopped hearing back after 15 seconds
2024-04-16 07:59:08.894 peer(NKrI…arBc) - Sending handshake initiation
2024-04-16 07:59:08.898 peer(NKrI…arBc) - Removing all keys, since we haven't received a new one in 540 seconds
2024-04-16 08:17:00.304 Network change detected with unsatisfied route and interface order [utun9, en0]
2024-04-16 08:17:00.335 Interface up requested
2024-04-16 08:17:00.474 Network change detected with satisfied route and interface order [en0, utun9]
2024-04-16 08:17:00.776 Network change detected with satisfied route and interface order [en0, utun9]
2024-04-16 08:17:01.224 Network change detected with satisfied route and interface order [en0, utun9]

Logging for native Wireguard app:

2024-04-16 09:42:02.033 [NET] peer(NKrI…arBc) - Failed to send data packet: write udp4 0.0.0.0:53083->145.x.x.x:51820: sendto: network is unreachable
2024-04-16 09:42:02.070 [NET] Network change detected with unsatisfied route and interface order [en0, utun4]
2024-04-16 09:42:02.085 [NET] Routine: receive incoming v4 - stopped
2024-04-16 09:42:02.085 [NET] Routine: receive incoming v6 - stopped
2024-04-16 09:42:02.086 [NET] UDP bind has been updated
2024-04-16 09:42:02.086 [NET] peer(NKrI…arBc) - Sending keepalive packet
2024-04-16 09:42:02.086 [NET] Routine: receive incoming v4 - started
2024-04-16 09:42:02.086 [NET] Routine: receive incoming v6 - started
2024-04-16 09:42:02.173 [NET] peer(NKrI…arBc) - Failed to send data packet: write udp4 0.0.0.0:53083->145.x.x.x:51820: sendto: network is unreachable
2024-04-16 09:42:02.201 [NET] Network change detected with unsatisfied route and interface order [utun4]
2024-04-16 09:42:02.216 [NET] Routine: receive incoming v4 - stopped
2024-04-16 09:42:02.217 [NET] Routine: receive incoming v6 - stopped
2024-04-16 09:42:02.217 [NET] UDP bind has been updated
2024-04-16 09:42:02.217 [NET] peer(NKrI…arBc) - Sending keepalive packet
2024-04-16 09:42:02.217 [NET] Routine: receive incoming v4 - started
2024-04-16 09:42:02.217 [NET] Routine: receive incoming v6 - started
2024-04-16 09:43:09.885 [NET] peer(NKrI…arBc) - Retrying handshake because we stopped hearing back after 15 seconds
2024-04-16 09:43:44.240 [APP] startDeactivation: Tunnel: TSwireguard
2024-04-16 09:43:44.259 [APP] Tunnel 'TSwireguard' connection status changed to 'disconnecting'
2024-04-16 09:43:44.777 [NET] Stopping tunnel
2024-04-16 09:44:04.446 [APP] Tunnel 'TSwireguard' connection status changed to 'disconnected'