efef
commented
4 years ago 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_pathstate [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
@efef reported earlier in https://github.com/eduvpn/apple/issues/307#issuecomment-639340006:
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.