Reconnect short after first connect: "Socket has a better path" #311

cyberjoost commented 2020年06月11日 19:23:33 +02:00 (Migrated from github.com)

@efef reported earlier in https://github.com/eduvpn/apple/issues/307#issuecomment-639340006:

On 10.15.4. I successfully connected the eduVPN app (2.1.7) to nl.eduvnp.org. The icon became 'green'. I did not yet see ipaddress. Next icon become yellow and reconnect happened spontaneously.

The following logging came with this comment:

connection_log.connect_disconnect_connect.txt
console_log.connect_disconnect_connect.txt

And logging for the same symptom again later:

disconnect2_console.txt
disconnect2.txt

@efef reported to me this symptom comes back every now and then, but it isn't clear when yet. There is no method known yet to reproduce this issue.

I had this exact same symptom before, but only one time, with both the eduVPN app and the Let's Connect app. In both cases the connection was restored after ~30 seconds. In logging I saw the same as in the logging provided by @efef :

2020年06月05日 10:20:48.117 DEBUG NEUDPSocket.observeValueInTunnelQueue():179 - Socket has a better path
2020年06月05日 10:20:48.117 DEBUG OpenVPNTunnelProvider.socketHasBetterPath():506 - Stopping tunnel due to a new better path
2020年06月05日 10:20:48.117 DEBUG OpenVPNTunnelProvider.logCurrentSSID():826 - Current SSID: none (disconnected from WiFi)
2020年06月05日 10:20:48.125 ERROR OpenVPNSession.doReconnect():1290 - Trigger reconnection (error: networkChanged)
2020年06月05日 10:20:48.125 ERROR OpenVPNTunnelProvider.sessionDidStop():584 - Session did stop with error: networkChanged

I didn't find a way yet to reproduce it (including a reboot for example), every subsequent Connect runs fine.

This symptom and logging "Socket has a better path" should happen in case "For example, if the session is established over a cellular data network and Wi-Fi is now available, then the session has a better path available" and will cause a reconnect. ( https://developer.apple.com/documentation/networkextension/nwudpsession/1406231-hasbetterpath )
It's not clear to me yet why this would happen in for example my case when I wasn't switching networks and upon a first connect.

@efef reported earlier in https://github.com/eduvpn/apple/issues/307#issuecomment-639340006: > On 10.15.4. I successfully connected the eduVPN app (2.1.7) to nl.eduvnp.org. The icon became 'green'. I did not yet see ipaddress. Next icon become yellow and reconnect happened spontaneously. The following logging came with this comment: [connection_log.connect_disconnect_connect.txt](https://github.com/eduvpn/apple/files/4766238/connection_log.connect_disconnect_connect.txt) [console_log.connect_disconnect_connect.txt](https://github.com/eduvpn/apple/files/4766239/console_log.connect_disconnect_connect.txt) And logging for the same symptom again later: [disconnect2_console.txt](https://github.com/eduvpn/apple/files/4766243/disconnect2_console.txt) [disconnect2.txt](https://github.com/eduvpn/apple/files/4766244/disconnect2.txt) @efef reported to me this symptom comes back every now and then, but it isn't clear when yet. There is no method known yet to reproduce this issue. I had this exact same symptom before, but only one time, with both the eduVPN app and the Let's Connect app. In both cases the connection was restored after ~30 seconds. In logging I saw the same as in the logging provided by @efef : 2020年06月05日 10:20:48.117 DEBUG NEUDPSocket.observeValueInTunnelQueue():179 - Socket has a better path 2020年06月05日 10:20:48.117 DEBUG OpenVPNTunnelProvider.socketHasBetterPath():506 - Stopping tunnel due to a new better path 2020年06月05日 10:20:48.117 DEBUG OpenVPNTunnelProvider.logCurrentSSID():826 - Current SSID: none (disconnected from WiFi) 2020年06月05日 10:20:48.125 ERROR OpenVPNSession.doReconnect():1290 - Trigger reconnection (error: networkChanged) 2020年06月05日 10:20:48.125 ERROR OpenVPNTunnelProvider.sessionDidStop():584 - Session did stop with error: networkChanged I didn't find a way yet to reproduce it (including a reboot for example), every subsequent Connect runs fine. This symptom and logging "Socket has a better path" should happen in case "For example, if the session is established over a cellular data network and Wi-Fi is now available, then the session has a better path available" and will cause a reconnect. ( https://developer.apple.com/documentation/networkextension/nwudpsession/1406231-hasbetterpath ) It's not clear to me yet why this would happen in for example my case when I wasn't switching networks and upon a first connect.

efef commented 2020年06月22日 14:55:42 +02:00 (Migrated from github.com)

I can quite trivial reproduce the issue in a 'clean' macOS VM. When I install the eduVPN app, next login to vpn.spoor.nu, the VPN connects and quickly disconnects.

In the App-log I read:
2020年06月22日 14:21:25.022 DEBUG NEUDPSocket.observeValueInTunnelQueue():179 - Socket has a better path
2020年06月22日 14:21:25.022 DEBUG OpenVPNTunnelProvider.socketHasBetterPath():506 - Stopping tunnel due to a new better path

Included are both the applog as console log. The console log was obtained by searching for "process eduVPN". This is the full log file including minutes before the event happened.

In console log is visible:
info 14:21:25.016728 +0200 EduVPNTunnelExtension-macOS nw_endpoint_handler_get_alternate_path_state [C1 IPv4#42722e29:1194 ready socket-flow (satisfied)] better path satisfied (Path is satisfied), interface: utun1, scoped, ipv4, ipv6 preferred to path satisfied (Path is satisfied), interface: en0, scoped, ipv4, dns

Get the impression, when the VPN turned ON, a new NIC (utun1) became available and the client thinks this utun1 is a better path than the native interface (en0).

connect_disconnect_21jun_applog.txt
connect_disconnect_21jun.txt

I can quite trivial reproduce the issue in a 'clean' macOS VM. When I install the eduVPN app, next login to vpn.spoor.nu, the VPN connects and quickly disconnects. In the App-log I read: _2020年06月22日 14:21:25.022 DEBUG NEUDPSocket.observeValueInTunnelQueue():179 - Socket has a better path 2020年06月22日 14:21:25.022 DEBUG OpenVPNTunnelProvider.socketHasBetterPath():506 - Stopping tunnel due to a new better path_ Included are both the applog as console log. The console log was obtained by searching for "process eduVPN". This is the full log file including minutes before the event happened. In console log is visible: _info 14:21:25.016728 +0200 EduVPNTunnelExtension-macOS nw_endpoint_handler_get_alternate_path_state [C1 IPv4#42722e29:1194 ready socket-flow (satisfied)] better path satisfied (Path is satisfied), interface: utun1, scoped, ipv4, ipv6 preferred to path satisfied (Path is satisfied), interface: en0, scoped, ipv4, dns_ Get the impression, when the VPN turned ON, a new NIC (utun1) became available and the client thinks this utun1 is a better path than the native interface (en0). [connect_disconnect_21jun_applog.txt](https://github.com/eduvpn/apple/files/4813214/connect_disconnect_21jun_applog.txt) [connect_disconnect_21jun.txt](https://github.com/eduvpn/apple/files/4813215/connect_disconnect_21jun.txt)

jwijenbergh commented 2026年02月17日 16:27:27 +01:00

Open for 5 years, are we still tackling this? Is this still an issue?

Open for 5 years, are we still tackling this? Is this still an issue?

efef commented 2026年03月13日 10:50:38 +01:00

An user reports, WiFi is flapping when connecting via openVPN, but with WireGuard there isn't an issue

--
2026年02月18日 09:17:35.480 2026年02月18日 09:17:35.480 INFO OpenVPNAdapter.sessionDidStart():528 - Search domains: not configured
2026年02月18日 09:17:35.480 2026年02月18日 09:17:35.480 INFO OpenVPNAdapter.bringNetworkUp():619 - Routing.IPv4: Setting default gateway to 145.90.232.129
2026年02月18日 09:17:35.480 2026年02月18日 09:17:35.480 INFO OpenVPNAdapter.bringNetworkUp():626 - Routing.IPv4: Adding route 0.0.0.0/0.0.0.0 -> 145.90.232.129
2026年02月18日 09:17:35.480 2026年02月18日 09:17:35.480 INFO OpenVPNAdapter.bringNetworkUp():656 - Routing.IPv6: Setting default gateway to 2001:610:450:b0::1:1
2026年02月18日 09:17:35.481 2026年02月18日 09:17:35.481 INFO OpenVPNAdapter.bringNetworkUp():733 - DNS: Using servers ["145.145.145.146", "2001:610:145:145:145:146::"]
2026年02月18日 09:17:35.481 2026年02月18日 09:17:35.481 DEBUG OpenVPNSession.sendAck():1280 - Ack successfully written to LINK for packetId 5
2026年02月18日 09:17:36.005 2026年02月18日 09:17:36.004 DEBUG OpenVPNAdapter.reasserting():149 - Reasserting flag cleared
2026年02月18日 09:17:36.005 2026年02月18日 09:17:36.005 INFO OpenVPNAdapter.sessionDidStart():564 - Tunnel interface is now UP
2026年02月18日 09:17:36.055 2026年02月18日 09:17:36.035 DEBUG OpenVPNAdapter.sessionDidStart():574 - Setting up path monitor
2026年02月18日 09:17:40.200 2026年02月18日 09:17:40.200 DEBUG NEUDPSocket.observeValueInTunnelQueue():169 - Socket has a better path
2026年02月18日 09:17:40.200 2026年02月18日 09:17:40.200 DEBUG OpenVPNAdapter.socketHasBetterPath():490 - Socket has better path. Path status: satisfied. Interfaces: [en0, en0, utun2]
2026年02月18日 09:17:40.200 2026年02月18日 09:17:40.200 DEBUG OpenVPNAdapter.socketHasBetterPath():492 - Path computed to be valid
2026年02月18日 09:17:40.201 2026年02月18日 09:17:40.201 DEBUG OpenVPNAdapter.socketHasBetterPath():498 - Stopping tunnel due to a new better path
2026年02月18日 09:17:40.212 2026年02月18日 09:17:40.212 DEBUG OpenVPNAdapter.logCurrentSSID():878 - Current SSID: none (disconnected from WiFi)
2026年02月18日 09:17:40.213 2026年02月18日 09:17:40.213 DEBUG OpenVPNSession.reconnect():308 - Initiating reconnect

An user reports, WiFi is flapping when connecting via openVPN, but with WireGuard there isn't an issue -- 2026年02月18日 09:17:35.480 2026年02月18日 09:17:35.480 INFO OpenVPNAdapter.sessionDidStart():528 - Search domains: not configured 2026年02月18日 09:17:35.480 2026年02月18日 09:17:35.480 INFO OpenVPNAdapter.bringNetworkUp():619 - Routing.IPv4: Setting default gateway to 145.90.232.129 2026年02月18日 09:17:35.480 2026年02月18日 09:17:35.480 INFO OpenVPNAdapter.bringNetworkUp():626 - Routing.IPv4: Adding route 0.0.0.0/0.0.0.0 -> 145.90.232.129 2026年02月18日 09:17:35.480 2026年02月18日 09:17:35.480 INFO OpenVPNAdapter.bringNetworkUp():656 - Routing.IPv6: Setting default gateway to 2001:610:450:b0::1:1 2026年02月18日 09:17:35.481 2026年02月18日 09:17:35.481 INFO OpenVPNAdapter.bringNetworkUp():733 - DNS: Using servers ["145.145.145.146", "2001:610:145:145:145:146::"] 2026年02月18日 09:17:35.481 2026年02月18日 09:17:35.481 DEBUG OpenVPNSession.sendAck():1280 - Ack successfully written to LINK for packetId 5 2026年02月18日 09:17:36.005 2026年02月18日 09:17:36.004 DEBUG OpenVPNAdapter.reasserting():149 - Reasserting flag cleared 2026年02月18日 09:17:36.005 2026年02月18日 09:17:36.005 INFO OpenVPNAdapter.sessionDidStart():564 - Tunnel interface is now UP 2026年02月18日 09:17:36.055 2026年02月18日 09:17:36.035 DEBUG OpenVPNAdapter.sessionDidStart():574 - Setting up path monitor 2026年02月18日 09:17:40.200 2026年02月18日 09:17:40.200 DEBUG NEUDPSocket.observeValueInTunnelQueue():169 - Socket has a better path 2026年02月18日 09:17:40.200 2026年02月18日 09:17:40.200 DEBUG OpenVPNAdapter.socketHasBetterPath():490 - Socket has better path. Path status: satisfied. Interfaces: [en0, en0, utun2] 2026年02月18日 09:17:40.200 2026年02月18日 09:17:40.200 DEBUG OpenVPNAdapter.socketHasBetterPath():492 - Path computed to be valid 2026年02月18日 09:17:40.201 2026年02月18日 09:17:40.201 DEBUG OpenVPNAdapter.socketHasBetterPath():498 - Stopping tunnel due to a new better path 2026年02月18日 09:17:40.212 2026年02月18日 09:17:40.212 DEBUG OpenVPNAdapter.logCurrentSSID():878 - Current SSID: none (disconnected from WiFi) 2026年02月18日 09:17:40.213 2026年02月18日 09:17:40.213 DEBUG OpenVPNSession.reconnect():308 - Initiating reconnect

roopc commented 2026年03月14日 13:55:41 +01:00

@efef What do you mean by "wifi is flapping"? Do you mean that while being connected to OpenVPN, wifi turns off, and then back on?

@efef What do you mean by "wifi is flapping"? Do you mean that while being connected to OpenVPN, wifi turns off, and then back on?

efef commented 2026年03月17日 11:45:53 +01:00

User reports, while connecting via openVPN (tunnelkit) the WiFi goes off/on, and I see in the log above " Current SSID: none (disconnected from WiFi)"

So it seems the better path also disconnects/connects WiFi somehow

User reports, while connecting via openVPN (tunnelkit) the WiFi goes off/on, and I see in the log above " Current SSID: none (disconnected from WiFi)" So it seems the better path also disconnects/connects WiFi somehow

efef commented 2026年03月19日 12:37:44 +01:00

Looks like the "hasbetterpath" function is deprecated, so we need to implement a newer way:

https://developer.apple.com/documentation/networkextension/nwudpsession/hasbetterpath

The user with the WiFi flapping issue, triggered by hasbetterpath, could solve the issue bij removing the network extension (settings - vpn) and rebooting the laptop.

Looks like the "hasbetterpath" function is deprecated, so we need to implement a newer way: https://developer.apple.com/documentation/networkextension/nwudpsession/hasbetterpath The user with the WiFi flapping issue, triggered by hasbetterpath, could solve the issue bij removing the network extension (settings - vpn) and rebooting the laptop.