Hello,
my boss (always with my boss!!! [:)]) tells me that his VPN is slow to open (some minutes!!). I have seen the log files, but it seems that the time spent in handshake is 24 seconds. Anyway the light becomes green only some minutes after. Can anyone know the reason?
This is the log file of client: (I have replaced some info's about our company. At the end of message you will see the asg log).
Fri Dec 11 07:07:47 2009 OpenVPN 2.1_rc19 i686-pc-cygwin [SSL] [LZO2] built on Aug 4 2009
Fri Dec 11 07:07:54 2009 WARNING: Make sure you understand the semantics of --tls-remote before using it (see the man page).
Fri Dec 11 07:07:54 2009 NOTE: OpenVPN 2.1 requires '--script-security 2' or higher to call user-defined scripts or executables
Fri Dec 11 07:07:55 2009 LZO compression initialized
Fri Dec 11 07:07:55 2009 Control Channel MTU parms [ L:1556 D:140 EF:40 EB:0 ET:0 EL:0 ]
Fri Dec 11 07:07:55 2009 Data Channel MTU parms [ L:1556 D:1450 EF:56 EB:135 ET:0 EL:0 AF:3/1 ]
Fri Dec 11 07:07:55 2009 Local Options hash (VER=V4): '619088b2'
Fri Dec 11 07:07:55 2009 Expected Remote Options hash (VER=V4): 'a4f12474'
Fri Dec 11 07:07:55 2009 Attempting to establish TCP connection with [MY PUBLIC IP ADDRESS]:443
Fri Dec 11 07:07:55 2009 TCP connection established with [MY PUBLIC IP ADDRESS]:443
Fri Dec 11 07:07:55 2009 Socket Buffers: R=[8192->8192] S=[8192->8192]
Fri Dec 11 07:07:55 2009 TCPv4_CLIENT link local: [undef]
Fri Dec 11 07:07:55 2009 TCPv4_CLIENT link remote: [MY PUBLIC IP ADDRESS]:443
Fri Dec 11 07:07:55 2009 TLS: Initial packet from [MY PUBLIC IP ADDRESS]:443, sid=f131fd53 2a43db51
Fri Dec 11 07:07:55 2009 WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Fri Dec 11 07:07:56 2009 VERIFY OK: depth=1, /C=it/L=Rome/O=***X/CN=[***XX_VPN]_CA/emailAddress=aaa@aaa.it
Fri Dec 11 07:07:56 2009 VERIFY X509NAME OK: /C=it/L=Rome/O=***X/CN=[MYHOSTNAME]/emailAddress=aaa@aaa.it
Fri Dec 11 07:07:56 2009 VERIFY OK: depth=0, /C=it/L=Rome/O=***X/CN=[MYHOSTNAME]/emailAddress=aaa@aaa.it
Fri Dec 11 07:07:59 2009 Data Channel Encrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
Fri Dec 11 07:07:59 2009 Data Channel Encrypt: Using 128 bit message hash 'MD5' for HMAC authentication
Fri Dec 11 07:07:59 2009 Data Channel Decrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
Fri Dec 11 07:07:59 2009 Data Channel Decrypt: Using 128 bit message hash 'MD5' for HMAC authentication
Fri Dec 11 07:07:59 2009 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
Fri Dec 11 07:07:59 2009 [[MYHOSTNAME]] Peer Connection Initiated with [MY PUBLIC IP ADDRESS]:443
Fri Dec 11 07:08:00 2009 SENT CONTROL [[MYHOSTNAME]]: 'PUSH_REQUEST' (status=1)
Fri Dec 11 07:08:01 2009 PUSH: Received control message: 'PUSH_REPLY,ifconfig 10.242.2.6 10.242.2.5,ping-restart 120,ping 10,topology net30,route 10.242.2.1,dhcp-option DOMAIN ***Xweb.roma,dhcp-option DNS 192.168.11.111,dhcp-option DNS 193.43.2.1,route 192.168.10.0 255.255.255.0,route 192.168.11.0 255.255.255.0'
Fri Dec 11 07:08:01 2009 OPTIONS IMPORT: timers and/or timeouts modified
Fri Dec 11 07:08:01 2009 OPTIONS IMPORT: --ifconfig/up options modified
Fri Dec 11 07:08:01 2009 OPTIONS IMPORT: route options modified
Fri Dec 11 07:08:01 2009 OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Fri Dec 11 07:08:01 2009 ROUTE default_gateway=192.168.1.1
Fri Dec 11 07:08:01 2009 TAP-WIN32 device [Connessione alla rete locale (LAN) 4] opened: \.\Global\{77453FA5-DF58-4F7A-B3E1-90CC63307579}.tap
Fri Dec 11 07:08:01 2009 TAP-Win32 Driver Version 9.6
Fri Dec 11 07:08:01 2009 TAP-Win32 MTU=1500
Fri Dec 11 07:08:01 2009 Notified TAP-Win32 driver to set a DHCP IP/netmask of 10.242.2.6/255.255.255.252 on interface {77453FA5-DF58-4F7A-B3E1-90CC63307579} [DHCP-serv: 10.242.2.5, lease-time: 31536000]
Fri Dec 11 07:08:01 2009 Successful ARP Flush on interface [4] {77453FA5-DF58-4F7A-B3E1-90CC63307579}
Fri Dec 11 07:08:06 2009 TEST ROUTES: 0/0 succeeded len=3 ret=0 a=0 u/d=down
Fri Dec 11 07:08:06 2009 Route: Waiting for TUN/TAP interface to come up...
Fri Dec 11 07:08:11 2009 TEST ROUTES: 3/3 succeeded len=3 ret=1 a=0 u/d=up
Fri Dec 11 07:08:11 2009 C:\WINDOWS\system32\route.exe ADD 192.168.11.0 MASK 255.255.255.0 10.242.2.5
Fri Dec 11 07:08:11 2009 Route addition via IPAPI succeeded [adaptive]
Fri Dec 11 07:08:11 2009 C:\WINDOWS\system32\route.exe ADD 192.168.10.0 MASK 255.255.255.0 10.242.2.5
Fri Dec 11 07:08:11 2009 Route addition via IPAPI succeeded [adaptive]
Fri Dec 11 07:08:11 2009 C:\WINDOWS\system32\route.exe ADD 10.242.2.1 MASK 255.255.255.255 10.242.2.5
Fri Dec 11 07:08:11 2009 Route addition via IPAPI succeeded [adaptive]
Fri Dec 11 07:08:11 2009 Initialization Sequence Completed
Fri Dec 11 07:33:14 2009 TCP/UDP: Closing socket
Fri Dec 11 07:33:14 2009 C:\WINDOWS\system32\route.exe DELETE 10.242.2.1 MASK 255.255.255.255 10.242.2.5
Fri Dec 11 07:33:14 2009 Route deletion via IPAPI succeeded [adaptive]
Fri Dec 11 07:33:14 2009 C:\WINDOWS\system32\route.exe DELETE 192.168.10.0 MASK 255.255.255.0 10.242.2.5
Fri Dec 11 07:33:14 2009 Route deletion via IPAPI succeeded [adaptive]
Fri Dec 11 07:33:14 2009 C:\WINDOWS\system32\route.exe DELETE 192.168.11.0 MASK 255.255.255.0 10.242.2.5
Fri Dec 11 07:33:14 2009 Route deletion via IPAPI succeeded [adaptive]
Fri Dec 11 07:33:14 2009 Closing TUN/TAP interface
Fri Dec 11 07:33:14 2009 SIGTERM[hard,] received, process exiting
This is the ASG log:
2009:12:11-07:06:20 ***XXfw openvpn[3953]: Re-using SSL/TLS context
2009:12:11-07:06:20 ***XXfw openvpn[3953]: LZO compression initialized
2009:12:11-07:06:20 ***XXfw openvpn[3953]: Control Channel MTU parms [ L:1556 D:140 EF:40 EB:0 ET:0 EL:0 ]
2009:12:11-07:06:20 ***XXfw openvpn[3953]: Data Channel MTU parms [ L:1556 D:1450 EF:56 EB:135 ET:0 EL:0 AF:3/1 ]
2009:12:11-07:06:20 ***XXfw openvpn[3953]: Local Options hash (VER=V4): 'a4f12474'
2009:12:11-07:06:20 ***XXfw openvpn[3953]: Expected Remote Options hash (VER=V4): '619088b2'
2009:12:11-07:06:20 ***XXfw openvpn[3953]: TCP connection established with 82.53.149.170:1047
2009:12:11-07:06:20 ***XXfw openvpn[3953]: TCPv4_SERVER link local: [undef]
2009:12:11-07:06:20 ***XXfw openvpn[3953]: TCPv4_SERVER link remote: 82.53.149.170:1047
2009:12:11-07:06:22 ***XXfw openvpn[3953]: 82.53.149.170:1047 VERIFY OK: depth=1, /C=it/L=Rome/O=***XX/CN=***XX_VPN_CA/emailAddress=aaa@aaa.it
2009:12:11-07:06:22 ***XXfw openvpn[3953]: 82.53.149.170:1047 VERIFY OK: depth=0, /C=it/L=Rome/O=***XX/CN=USERNAME/emailAddress=username@***XXweb.com
2009:12:11-07:06:24 ***XXfw openvpn[3953]: 82.53.149.170:1047 TLS: Username/Password authentication succeeded for username 'username'
2009:12:11-07:06:24 ***XXfw openvpn[3953]: 82.53.149.170:1047 Data Channel Encrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
2009:12:11-07:06:24 ***XXfw openvpn[3953]: 82.53.149.170:1047 Data Channel Encrypt: Using 128 bit message hash 'MD5' for HMAC authentication
2009:12:11-07:06:24 ***XXfw openvpn[3953]: 82.53.149.170:1047 Data Channel Decrypt: Cipher 'AES-128-CBC' initialized with 128 bit key
2009:12:11-07:06:24 ***XXfw openvpn[3953]: 82.53.149.170:1047 Data Channel Decrypt: Using 128 bit message hash 'MD5' for HMAC authentication
2009:12:11-07:06:25 ***XXfw openvpn[3953]: 82.53.149.170:1047 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
2009:12:11-07:06:25 ***XXfw openvpn[3953]: 82.53.149.170:1047 [USERNAME] Peer Connection Initiated with 82.53.149.170:1047
2009:12:11-07:31:39 ***XXfw openvpn[3953]: USERNAME/82.53.149.170:1047 Connection reset, restarting [-1]
2009:12:11-07:31:40 ***XXfw openvpn[3953]: TCP/UDP: Closing socket
Thank you
eclipse79
This thread was automatically locked due to age.