search

schwabe / ics-openvpn

OpenVPN for Android
3.37k stars 1.2k forks source link

Reconnection after restoring internet connection not working #1244

Open hhp21 opened 4 years ago

hhp21 commented 4 years ago

General information

  1. Android Version: 9
  2. Android Vendor/Custom ROM: ChromeOS version 85.0.4183.133 64-bit
  3. Device: Pixelbook Go
  4. Version of the app (version number/play store version/self-built): 0.7.21 (installed from Play Store)

Description of the issue

I have a working VPN connection, but if I put the machine to sleep (e.g. by closing it) and then come back to it, OpenVPN for Android will say that it has successfully reconnected, when in fact the VPN connection doesn't work. Manually reconnecting will fix the connection.

... These are logs during a working connection ...

2020-10-01 23:29:55 Opening tun interface:
2020-10-01 23:29:55 Local IPv4: 10.8.0.146/30 IPv6: (not set) MTU: 1500
2020-10-01 23:29:55 DNS Server: 8.8.8.8, 8.8.4.4 <redacted>
2020-10-01 23:29:55 Routes: 10.8.0.1/32, 10.8.0.144/30, 172.30.0.0/16 
2020-10-01 23:29:55 Routes excluded: <redacted>
2020-10-01 23:29:55 VpnService routes installed: 10.8.0.1/32, 10.8.0.144/30, 172.30.0.0/16 
2020-10-01 23:29:55 Disallowed VPN apps: 
2020-10-01 23:29:55 MANAGEMENT: CMD 'needok 'OPENTUN' ok'
2020-10-01 23:29:55 Initialization Sequence Completed
2020-10-01 23:29:55 MANAGEMENT: >STATE:1601591395,CONNECTED,SUCCESS,10.8.0.146,<redacted>

... Then the machine went to sleep, then when it was restored ...

2020-10-02 12:33:10 Network Status: not connected
2020-10-02 12:33:10 Debug state info: not connected, pause: userPause, shouldbeconnected: false, network: PENDINGDISCONNECT 
2020-10-02 12:33:11 [server] Inactivity timeout (--ping-restart), restarting
2020-10-02 12:33:11 TCP/UDP: Closing socket
2020-10-02 12:33:11 SIGUSR1[soft,ping-restart] received, process restarting
2020-10-02 12:33:11 MANAGEMENT: >STATE:1601638391,RECONNECTING,ping-restart,,,,,
2020-10-02 12:33:15 MANAGEMENT: CMD 'hold release'
2020-10-02 12:33:15 MANAGEMENT: CMD 'proxy NONE'
2020-10-02 12:33:15 MANAGEMENT: CMD 'bytecount 2'
2020-10-02 12:33:15 MANAGEMENT: CMD 'state on'
2020-10-02 12:33:15 Network Status: CONNECTED  to WIFI SSID_1
2020-10-02 12:33:15 Debug state info: CONNECTED  to WIFI SSID_1, pause: userPause, shouldbeconnected: true, network: SHOULDBECONNECTED 
2020-10-02 12:33:16 Control Channel MTU parms [ L:1621 D:1212 EF:38 EB:0 ET:0 EL:3 ]
2020-10-02 12:33:16 Data Channel MTU parms [ L:1621 D:1450 EF:121 EB:406 ET:0 EL:3 ]
2020-10-02 12:33:16 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-client'
2020-10-02 12:33:16 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1549,tun-mtu 1500,proto UDPv4,cipher AES-256-GCM,auth [null-digest],keysize 256,key-method 2,tls-server'
2020-10-02 12:33:16 TCP/UDP: Preserving recently used remote address: [AF_INET]<redacted>
2020-10-02 12:33:16 Socket Buffers: R=[212992->212992] S=[212992->212992]
2020-10-02 12:33:16 MANAGEMENT: CMD 'needok 'PROTECTFD' ok'
2020-10-02 12:33:16 UDP link local: (not bound)
2020-10-02 12:33:16 UDP link remote: [AF_INET]<redacted>
2020-10-02 12:33:16 MANAGEMENT: >STATE:1601638396,WAIT,,,,,,
2020-10-02 12:33:16 MANAGEMENT: >STATE:1601638396,AUTH,,,,,,
2020-10-02 12:33:16 TLS: Initial packet from [AF_INET]<redacted>, sid=d145ee66 91040e9f
2020-10-02 12:33:16 VERIFY KU OK
2020-10-02 12:33:16 Validating certificate extended key usage
2020-10-02 12:33:16 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
2020-10-02 12:33:16 VERIFY EKU OK
2020-10-02 12:33:16 VERIFY OK: depth=0, CN=server
2020-10-02 12:33:16 Control Channel: TLSv1.2, cipher TLSv1.2 ECDHE-RSA-AES256-GCM-SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256
2020-10-02 12:33:16 [server] Peer Connection Initiated with [AF_INET]<redacted>
2020-10-02 12:33:18 MANAGEMENT: >STATE:1601638398,GET_CONFIG,,,,,,
2020-10-02 12:33:18 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
2020-10-02 12:33:18 PUSH: Received control message: <redacted>
2020-10-02 12:33:18 OPTIONS IMPORT: timers and/or timeouts modified
2020-10-02 12:33:18 OPTIONS IMPORT: --ifconfig/up options modified
2020-10-02 12:33:18 OPTIONS IMPORT: route options modified
2020-10-02 12:33:18 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
2020-10-02 12:33:18 OPTIONS IMPORT: peer-id set
2020-10-02 12:33:18 OPTIONS IMPORT: adjusting link_mtu to 1624
2020-10-02 12:33:18 OPTIONS IMPORT: data channel crypto options modified
2020-10-02 12:33:18 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2020-10-02 12:33:18 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key
2020-10-02 12:33:18 ROUTE_GATEWAY 127.100.103.119 IFACE=android-gw
2020-10-02 12:33:18 do_ifconfig, ipv4=1, ipv6=0
2020-10-02 12:33:18 MANAGEMENT: >STATE:1601638398,ASSIGN_IP,,10.8.0.146,,,,
2020-10-02 12:33:18 MANAGEMENT: CMD 'needok 'IFCONFIG' ok'
2020-10-02 12:33:18 MANAGEMENT: >STATE:1601638398,ADD_ROUTES,,,,,,
2020-10-02 12:33:18 MANAGEMENT: CMD 'needok 'ROUTE' ok'
2020-10-02 12:33:18 MANAGEMENT: CMD 'needok 'ROUTE' ok'
2020-10-02 12:33:18 MANAGEMENT: CMD 'needok 'DNSSERVER' ok'
2020-10-02 12:33:18 MANAGEMENT: CMD 'needok 'DNSSERVER' ok'
2020-10-02 12:33:18 MANAGEMENT: CMD 'needok 'DNSSERVER' ok'
2020-10-02 12:33:18 MANAGEMENT: CMD 'needok 'DNSDOMAIN' ok'
2020-10-02 12:33:18 MANAGEMENT: CMD 'needok 'PERSIST_TUN_ACTION' OPEN_BEFORE_CLOSE'
2020-10-02 12:33:18 Opening tun interface:
2020-10-02 12:33:18 Local IPv4: 10.8.0.146/30 IPv6: (not set) MTU: 1500
2020-10-02 12:33:18 DNS Server: 8.8.8.8, 8.8.4.4, <redacted>
2020-10-02 12:33:18 Routes: 10.8.0.1/32, 10.8.0.144/30, 172.30.0.0/16 
2020-10-02 12:33:18 Routes excluded: 100.115.92.14/30 fe80:0:0:0:8e5:7fff:fed8:1aca/64
2020-10-02 12:33:18 VpnService routes installed: 10.8.0.1/32, 10.8.0.144/30, 172.30.0.0/16 
2020-10-02 12:33:18 Disallowed VPN apps: 
2020-10-02 12:33:18 MANAGEMENT: CMD 'needok 'OPENTUN' ok'
2020-10-02 12:33:18 Initialization Sequence Completed
2020-10-02 12:33:18 MANAGEMENT: >STATE:1601638398,CONNECTED,SUCCESS,10.8.0.146,<redacted>,,

It definitely attempts to reconnect, as seen in the logs, and claims it was successful. The server-side logs also shows a record of the reconnection and they are indistinguishable from a proper working connection attempt. And yet the connection doesn't work. Any ideas where I could look further?

schwabe commented 4 years ago

I am not sure what is wrong here. From the apps view it has done everything to connect the VPN and even got the okay from the OS. This might be a problem from Chrome OS.