schwabe
commented
3 years ago Try switching my App to use OpenVPN3 core and see if the time difference goes away.
But you really should check the server log. The client is waiting for over 10s for a server reply:
021-09-15 11:13:51 [.ros-ovpn-vpn-dtops.cc] Peer Connection Initiated with [AF_INET]123.121.134.60:8194
2021-09-15 11:13:52 MANAGEMENT: >STATE:1631675632,GET_CONFIG,,,,,,
2021-09-15 11:13:52 SENT CONTROL [.ros-ovpn-vpn-dtops.cc]: 'PUSH_REQUEST' (status=1)
2021-09-15 11:13:57 SENT CONTROL [.ros-ovpn-vpn-dtops.cc]: 'PUSH_REQUEST' (status=1)
2021-09-15 11:13:57 Key [AF_INET]123.121.134.60:8194 [0] not initialized (yet), dropping packet.
2021-09-15 11:14:02 SENT CONTROL [*.ros-ovpn-vpn-dtops.cc]: 'PUSH_REQUEST' (status=1)
2021-09-15 11:14:02 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 114.114.114.114,dhcp-option DNS 223.5.5.5,ping 100,ping-restart 300,topology subnet,route-gateway 10.0.4.254,ifconfig 10.0.4.137 255.255.255.0'
I used OpenVPN and OpenVPN to test and found that their connection times were different. This is the log.
OPENVPNCONNECT log. 11:12:55.419 -- ----- OpenVPN Start -----
11:12:55.419 -- EVENT: CORE_THREAD_ACTIVE
11:12:55.421 -- OpenVPN core 3.git:released:662eae9a:Release android arm64 64-bit PT_PROXY
11:12:55.428 -- Frame=512/2048/512 mssfix-ctrl=1250
11:12:55.435 -- UNUSED OPTIONS 4 [nobind] 5 [persist-key] 6 [persist-tun] 7 [tls-client] 9 [verb] [4] 10 [mute] [10] 14 [auth-nocache]
11:12:55.436 -- EVENT: RESOLVE
11:12:55.438 -- Contacting 123.121.134.60:8194 via TCPv4
11:12:55.439 -- EVENT: WAIT
11:12:55.492 -- Connecting to [123.121.134.60]:8194 (123.121.134.60) via TCPv4
11:12:55.533 -- EVENT: CONNECTING
11:12:55.577 -- Tunnel Options:V4,dev-type tun,link-mtu 1559,tun-mtu 1500,proto TCPv4_CLIENT,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client
11:12:55.578 -- Creds: Username/Password
11:12:55.579 -- Peer Info: IV_VER=3.git:released:662eae9a:Release IV_PLAT=android IV_NCP=2 IV_TCPNL=1 IV_PROTO=2 IV_GUI_VER=net.openvpn.connect.android_3.2.4-5891 IV_SSO=openurl
11:12:55.753 -- VERIFY OK: depth=0, /CN=*.ros-ovpn-vpn-dtops.cc
11:12:56.162 -- SSL Handshake: CN=*.ros-ovpn-vpn-dtops.cc, TLSv1.2, cipher TLSv1.2 DHE-RSA-AES256-GCM-SHA384, 2048 bit RSA
11:12:56.163 -- Session is ACTIVE
11:12:56.166 -- EVENT: GET_CONFIG
11:12:56.171 -- Sending PUSH_REQUEST to server...
11:12:57.165 -- Sending PUSH_REQUEST to server...
11:12:59.168 -- Sending PUSH_REQUEST to server...
11:12:59.246 -- OPTIONS: 0 [redirect-gateway] 1 [dhcp-option] [DNS] [114.114.114.114] 2 [dhcp-option] [DNS] [223.5.5.5] 3 [ping] [100] 4 [ping-restart] [300] 5 [topology] [subnet] 6 [route-gateway] [10.0.4.254] 7 [ifconfig] [10.0.4.137] [255.255.255.0]
11:12:59.249 -- PROTOCOL OPTIONS: cipher: AES-256-CBC digest: SHA1 compress: NONE peer ID: -1
11:12:59.253 -- EVENT: ASSIGN_IP
11:12:59.309 -- Connected via tun
11:12:59.314 -- EVENT: CONNECTED info='xmdlkxlr@123.121.134.60:8194 (123.121.134.60) via /TCPv4 on tun/10.0.4.137/ gw=[10.0.4.254/]' trans=TO_CONNECTED
OPENVPN log 2021-09-15 11:13:44 运行于 HUAWEI VKY-AL00 (VKY)，安卓 7.0 (HUAWEIVKY-AL00) 应用程序接口 24，应用二进制接口 arm64-v8a, (HUAWEI/VKY-AL00/HWVKY:7.0/HUAWEIVKY-AL00/C00B172:user/release-keys) 上的正式版本 0.7.22 2021-09-15 11:13:50 构建配置中... 2021-09-15 11:13:50 started Socket Thread 2021-09-15 11:13:50 网络状态：CONNECTED to WIFI "MQ" 2021-09-15 11:13:50 Debug state info: CONNECTED to WIFI "MQ", pause: userPause, shouldbeconnected: true, network: SHOULDBECONNECTED 2021-09-15 11:13:50 Debug state info: CONNECTED to WIFI "MQ", pause: userPause, shouldbeconnected: true, network: SHOULDBECONNECTED 2021-09-15 11:13:50 Current Parameter Settings: 2021-09-15 11:13:50 config = '/data/user/0/de.blinkt.openvpn/cache/android.conf' 2021-09-15 11:13:50 mode = 0 2021-09-15 11:13:50 show_ciphers = DISABLED 2021-09-15 11:13:50 show_digests = DISABLED 2021-09-15 11:13:50 show_engines = DISABLED 2021-09-15 11:13:50 genkey = DISABLED 2021-09-15 11:13:50 genkey_filename = '[UNDEF]' 2021-09-15 11:13:50 key_pass_file = '[UNDEF]' 2021-09-15 11:13:50 show_tls_ciphers = DISABLED 2021-09-15 11:13:50 NOTE: --mute triggered... 2021-09-15 11:13:50 224 variation(s) on previous 10 message(s) suppressed by --mute 2021-09-15 11:13:50 OpenVPN 2.5-icsopenvpn [git:icsopenvpn/v0.7.22-0-g9b79d2c5] arm64-v8a [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Mar 15 2021 2021-09-15 11:13:50 library versions: OpenSSL 1.1.1j 16 Feb 2021, LZO 2.10 2021-09-15 11:13:50 MANAGEMENT: Connected to management server at /data/user/0/de.blinkt.openvpn/cache/mgmtsocket 2021-09-15 11:13:50 MANAGEMENT: CMD 'version 3' 2021-09-15 11:13:50 等待0秒进行下一次连接尝试 2021-09-15 11:13:50 MANAGEMENT: CMD 'hold release' 2021-09-15 11:13:50 MANAGEMENT: CMD 'bytecount 2' 2021-09-15 11:13:50 MANAGEMENT: CMD 'username 'Auth' xmdlkxlr' 2021-09-15 11:13:50 MANAGEMENT: CMD 'state on' 2021-09-15 11:13:50 MANAGEMENT: CMD 'password [...]' 2021-09-15 11:13:50 MANAGEMENT: CMD 'proxy NONE' 2021-09-15 11:13:51 MANAGEMENT: CMD 'password [...]' 2021-09-15 11:13:51 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this 2021-09-15 11:13:51 Control Channel MTU parms [ L:1623 D:1210 EF:40 EB:0 ET:0 EL:3 ] 2021-09-15 11:13:51 Data Channel MTU parms [ L:1623 D:1450 EF:123 EB:406 ET:0 EL:3 ] 2021-09-15 11:13:51 Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1559,tun-mtu 1500,proto TCPv4_CLIENT,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-client' 2021-09-15 11:13:51 Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1559,tun-mtu 1500,proto TCPv4_SERVER,cipher AES-256-CBC,auth SHA1,keysize 256,key-method 2,tls-server' 2021-09-15 11:13:51 TCP/UDP: Preserving recently used remote address: [AF_INET]123.121.134.60:8194 2021-09-15 11:13:51 Socket Buffers: R=[1048576->1048576] S=[524288->524288] 2021-09-15 11:13:51 Attempting to establish TCP connection with [AF_INET]123.121.134.60:8194 [nonblock] 2021-09-15 11:13:51 MANAGEMENT: >STATE:1631675631,TCP_CONNECT,,,,,, 2021-09-15 11:13:51 MANAGEMENT: CMD 'needok 'PROTECTFD' ok' 2021-09-15 11:13:51 TCP connection established with [AF_INET]123.121.134.60:8194 2021-09-15 11:13:51 MANAGEMENT: CMD 'needok 'PROTECTFD' ok' 2021-09-15 11:13:51 TCP_CLIENT link local: (not bound) 2021-09-15 11:13:51 TCP_CLIENT link remote: [AF_INET]123.121.134.60:8194 2021-09-15 11:13:51 MANAGEMENT: >STATE:1631675631,WAIT,,,,,, 2021-09-15 11:13:51 MANAGEMENT: >STATE:1631675631,AUTH,,,,,, 2021-09-15 11:13:51 TLS: Initial packet from [AF_INET]123.121.134.60:8194, sid=9cd8e2f6 159f9b3f 2021-09-15 11:13:51 VERIFY OK: depth=1, CN=ros-ovpn-vpn-dtops.cc 2021-09-15 11:13:51 VERIFY KU OK 2021-09-15 11:13:51 Validating certificate extended key usage 2021-09-15 11:13:51 ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication 2021-09-15 11:13:51 VERIFY EKU OK 2021-09-15 11:13:51 VERIFY OK: depth=0, CN=.ros-ovpn-vpn-dtops.cc 2021-09-15 11:13:51 Control Channel: TLSv1.2, cipher TLSv1.2 DHE-RSA-AES256-GCM-SHA384, peer certificate: 2048 bit RSA, signature: RSA-SHA256 2021-09-15 11:13:51 [.ros-ovpn-vpn-dtops.cc] Peer Connection Initiated with [AF_INET]123.121.134.60:8194 2021-09-15 11:13:52 MANAGEMENT: >STATE:1631675632,GET_CONFIG,,,,,, 2021-09-15 11:13:52 SENT CONTROL [.ros-ovpn-vpn-dtops.cc]: 'PUSH_REQUEST' (status=1) 2021-09-15 11:13:57 SENT CONTROL [.ros-ovpn-vpn-dtops.cc]: 'PUSH_REQUEST' (status=1) 2021-09-15 11:13:57 Key [AF_INET]123.121.134.60:8194 [0] not initialized (yet), dropping packet. 2021-09-15 11:14:02 SENT CONTROL [*.ros-ovpn-vpn-dtops.cc]: 'PUSH_REQUEST' (status=1) 2021-09-15 11:14:02 PUSH: Received control message: 'PUSH_REPLY,dhcp-option DNS 114.114.114.114,dhcp-option DNS 223.5.5.5,ping 100,ping-restart 300,topology subnet,route-gateway 10.0.4.254,ifconfig 10.0.4.137 255.255.255.0' 2021-09-15 11:14:02 OPTIONS IMPORT: timers and/or timeouts modified 2021-09-15 11:14:02 OPTIONS IMPORT: --ifconfig/up options modified 2021-09-15 11:14:02 OPTIONS IMPORT: route-related options modified 2021-09-15 11:14:02 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified 2021-09-15 11:14:02 Using peer cipher 'AES-256-CBC' 2021-09-15 11:14:02 Outgoing Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key 2021-09-15 11:14:02 Outgoing Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication 2021-09-15 11:14:02 Incoming Data Channel: Cipher 'AES-256-CBC' initialized with 256 bit key 2021-09-15 11:14:02 Incoming Data Channel: Using 160 bit message hash 'SHA1' for HMAC authentication 2021-09-15 11:14:02 ROUTE_GATEWAY 127.100.103.119 IFACE=android-gw 2021-09-15 11:14:02 do_ifconfig, ipv4=1, ipv6=0 2021-09-15 11:14:02 MANAGEMENT: >STATE:1631675642,ASSIGN_IP,,10.0.4.137,,,, 2021-09-15 11:14:02 MANAGEMENT: CMD 'needok 'IFCONFIG' ok' 2021-09-15 11:14:02 MANAGEMENT: >STATE:1631675642,ADD_ROUTES,,,,,, 2021-09-15 11:14:02 MANAGEMENT: CMD 'needok 'ROUTE' ok' 2021-09-15 11:14:02 MANAGEMENT: CMD 'needok 'DNSSERVER' ok' 2021-09-15 11:14:02 MANAGEMENT: CMD 'needok 'DNSSERVER' ok' 2021-09-15 11:14:02 MANAGEMENT: CMD 'needok 'PERSIST_TUN_ACTION' OPEN_BEFORE_CLOSE' 2021-09-15 11:14:02 正在打开 tun 设备： 2021-09-15 11:14:02 本地 IPv4：10.0.4.137/24 IPv6：(not set) MTU：1500 2021-09-15 11:14:02 DNS 服务器：114.114.114.114, 223.5.5.5，域名：null 2021-09-15 11:14:02 路由：0.0.0.0/0, 10.0.4.0/24 2021-09-15 11:14:02 排除的路由：10.3.0.41/24 fe80:0:0:0:5ec3:7ff:fe80:631e/64 2021-09-15 11:14:02 已安装的VpnService 路由：0.0.0.0/5, 8.0.0.0/7, 10.0.0.0/15, 10.2.0.0/16, 10.3.1.0/24, 10.3.2.0/23, 10.3.4.0/22, 10.3.8.0/21, 10.3.16.0/20, 10.3.32.0/19, 10.3.64.0/18, 10.3.128.0/17, 10.4.0.0/14, 10.8.0.0/13, 10.16.0.0/12, 10.32.0.0/11, 10.64.0.0/10, 10.128.0.0/9, 11.0.0.0/8, 12.0.0.0/6, 16.0.0.0/4, 32.0.0.0/3, 64.0.0.0/2, 128.0.0.0/1 2021-09-15 11:14:02 不允许通过VPN的应用： 2021-09-15 11:14:02 MANAGEMENT: CMD 'needok 'OPENTUN' ok' 2021-09-15 11:14:02 Initialization Sequence Completed 2021-09-15 11:14:02 MANAGEMENT: >STATE:1631675642,CONNECTED,SUCCESS,10.0.4.137,123.121.134.60,8194,10.3.0.41,39525 2021-09-15 11:14:02 Debug state info: CONNECTED to WIFI "MQ", pause: userPause, shouldbeconnected: true, network: SHOULDBECONNECTED
Is there any difference between the two app connection processes? Can you help me explain why the time gap is so big？