About connection time #1365

MrMercedes · 2021-09-15T03:41:04Z

MrMercedes
Sep 15, 2021

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？

schwabe · 2021-09-15T11:14:12Z

schwabe
Sep 15, 2021
Maintainer

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'

2 replies

MrMercedes Sep 16, 2021
Author

2021-09-16 11:41:42 运行于 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-16 11:41:48 构建配置中...
2021-09-16 11:41:48 网络状态：CONNECTED to WIFI "MQ"
2021-09-16 11:41:48 Debug state info: CONNECTED to WIFI "MQ", pause: userPause, shouldbeconnected: true, network: SHOULDBECONNECTED
2021-09-16 11:41:48 Debug state info: CONNECTED to WIFI "MQ", pause: userPause, shouldbeconnected: true, network: SHOULDBECONNECTED
2021-09-16 11:41:48 OpenVPN core 3.6_git:master(icsopenvpn/v0.7.22-0-g0d2b0801) android arm64 64-bit
2021-09-16 11:41:48 Copyright (C) 2012-2020 OpenVPN Inc. All rights reserved.
2021-09-16 11:41:48 OpenVPN core 3.6_git:master(icsopenvpn/v0.7.22-0-g0d2b0801) android arm64 64-bit
2021-09-16 11:41:48 Frame=512/2048/512 mssfix-ctrl=1250
2021-09-16 11:41:48 connect() error: : PKey::parse_pem: error in private key:: error:06065064:digital envelope routines:EVP_DecryptFinal_ex:bad decrypt / error:23077074:PKCS12 routines:PKCS12_pbe_crypt:pkcs12 cipherfinal error / error:2306A075:PKCS12 routines:PKCS12_item_decrypt_d2i:pkcs12 pbe ...

I switch the App to OpenVPN3 core，“PKey::parse_pem: error in private key”. Thank you,I will check the server.

schwabe Sep 16, 2021
Maintainer

Hm pkcs12 support in OpenVPN3 core might not be working. That is a long standing issue. Try importing the pkcs12 into the android store to use that pkcs12

schwabe · 2021-09-15T11:55:27Z

schwabe
Sep 15, 2021
Maintainer

As a sidenote, the server does NOT push --cipher. So it is probably a very old server like OpenVPN 2.3.x.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

About connection time #1365

{{title}}

Replies: 2 comments 2 replies

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

About connection time #1365

MrMercedes Sep 15, 2021

Replies: 2 comments · 2 replies

schwabe Sep 15, 2021 Maintainer

MrMercedes Sep 16, 2021 Author

schwabe Sep 16, 2021 Maintainer

schwabe Sep 15, 2021 Maintainer

MrMercedes
Sep 15, 2021

Replies: 2 comments 2 replies

schwabe
Sep 15, 2021
Maintainer

MrMercedes Sep 16, 2021
Author

schwabe Sep 16, 2021
Maintainer

schwabe
Sep 15, 2021
Maintainer