Disconnected after 62 minutes

Got a problem with Viscosity or need help? Ask here!

DonnEdwards

Posts: 10
Joined: Fri Jun 28, 2013 7:00 pm

Post by DonnEdwards » Sun Jun 30, 2013 4:38 am
My connection to SwissVPN works fine for the first hour:
Code: Select all
 (snip)
Jun 29 07:17:08: Initialization Sequence Completed
Jun 29 07:17:08: State changed to Connected
Jun 29 08:19:58: Connection reset, restarting [0]
Jun 29 08:19:58: SIGUSR1[soft,connection-reset] received, process restarting
Jun 29 08:19:58: State changed to Connecting
As you can see the connection was established ad 07:17:08 and everything work fine until 08:19:58.
At this point the connection seems to be broken (ping times out, no browsing or connectivity)

The state changes to "Connecting" but nothing further happens. Yesterday I left it overnight and it was still "connecting" in the morning, some 12 hours later.

If I manually disconnect and then reconnect, the connection will work again for another hour.

I have asked SwissVPN whether they are sending the SIGUSR1 signal, but heard no reply yet.

Is it possible that my own ISP is interfering with the connection? I doubt it but needed to ask. No other traffic is affected this way.

Are there any settings I can set on Viscosity so that the automatic reconnect doesn't freeze? I have tried the "Options" tab in "Edit Connections" and set Ping=10 and Ping Restart=3600 but I don't understand what this means and in any case I'm still getting the freezing.

I have checked my AV logs and there is no mention of any unwanted virus traffic or anything. Also, the disconnection happens even if the only traffic is a continuous ping to 8.8.8.8

Any suggestions I can try to reconnect successfully?
Donn Edwards
Johannesburg, South Africa

Eric

User avatar
Posts: 1146
Joined: Sun Jan 03, 2010 3:27 am

Post by Eric » Mon Jul 01, 2013 8:44 am
Hi Donn,

This will be an issue at your VPN Providers end terminating then rejecting your session. I would recommend awaiting their reply.

It is possible though that either your router or your ISP is interrupting the connection, though unlikely.

As for the reconnect failing, this could be caused by AV software interfering or a custom route that is preventing the server being contacted again. We would need a full log from connection through reconnection being stuck to make any sense of it though. If you could add 'verb 5' to the Advanced section of your connection configuration that would provide us with some additional detail.

Unfortunately Viscosity does not have a feature built in to disconnect and reconnect in this unique scenario.

Regards,

Eric
Eric Thorpe
Viscosity Developer

Web: http://www.sparklabs.com
Support: http://www.sparklabs.com/support
Twitter: http://twitter.com/sparklabs

DonnEdwards

Posts: 10
Joined: Fri Jun 28, 2013 7:00 pm

Post by DonnEdwards » Mon Jul 01, 2013 9:37 pm
Does any of this help?
Code: Select all
Jul 01 01:15:40: State changed to Connecting
Jul 01 01:15:40: Viscosity 1.4.4 (1191)
Jul 01 01:15:40: Running on Microsoft Windows 7 Home Premium 
Jul 01 01:15:41: Bringing up interface...
Jul 01 01:15:41: Checking reachability status of connection...
Jul 01 01:15:41: Connection is reachable. Starting connection attempt.
Jul 01 01:15:42: 52160 Mon Jul 01 13:15:42 2013 us=515000 Current Parameter Settings:
Jul 1 01:15:42: MANAGEMENT: CMD 'state on'
Jul 1 01:15:42: MANAGEMENT: CMD ''
Jul 1 01:15:42: MANAGEMENT: CMD 'hold release'
Jul 1 01:15:42: MANAGEMENT: CMD ''
Jul 1 01:15:42: MANAGEMENT: CMD 'username "Auth" "bgtspuzb"'
Jul 1 01:15:42: MANAGEMENT: CMD 'password [...]'
Jul 1 01:15:42: MANAGEMENT: CMD ''
Jul 1 01:15:43: WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Jul 1 01:15:43: NOTE: OpenVPN 2.1 requires '--script-security 2' or higher to call user-defined scripts or executables
Jul 1 01:15:43: Control Channel MTU parms [ L:1543 D:140 EF:40 EB:0 ET:0 EL:0 ]
Jul 1 01:15:43: Socket Buffers: R=[8192->8192] S=[8192->8192]
Jul 1 01:15:43: MANAGEMENT: >STATE:1372677343,RESOLVE,,,
Jul 1 01:15:43: RESOLVE: NOTE: connect-openvpn.swissvpn.net resolves to 3 addresses
Jul 1 01:15:43: Data Channel MTU parms [ L:1543 D:1450 EF:43 EB:4 ET:0 EL:0 ]
Jul 1 01:15:43: Local Options String: 'V4,dev-type tun,link-mtu 1543,tun-mtu 1500,proto TCPv4_CLIENT,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Jul 1 01:15:43: Expected Remote Options String: 'V4,dev-type tun,link-mtu 1543,tun-mtu 1500,proto TCPv4_SERVER,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Jul 1 01:15:43: Local Options hash (VER=V4): 'db02a8f8'
Jul 1 01:15:43: Expected Remote Options hash (VER=V4): '7e068940'
Jul 1 01:15:43: Attempting to establish TCP connection with 80.254.79.101:443
Jul 1 01:15:43: MANAGEMENT: >STATE:1372677343,TCP_CONNECT,,,
Jul 1 01:15:43: TCP connection established with 80.254.79.101:443
Jul 1 01:15:43: TCPv4_CLIENT link local: [undef]
Jul 1 01:15:43: TCPv4_CLIENT link remote: 80.254.79.101:443
Jul 1 01:15:43: MANAGEMENT: >STATE:1372677343,WAIT,,,
Jul 1 01:15:43: MANAGEMENT: >STATE:1372677344,AUTH,,,
Jul 1 01:15:43: TLS: Initial packet from 80.254.79.101:443, sid=f2c94e3b becb3309
Jul 1 01:15:43: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Jul 1 01:15:47: VERIFY OK: depth=1, /C=CH/ST=ZH/L=Regensdorf/O=Monzoon_Networks_AG/OU=OpenVPN_CA/CN=OpenVPN-CA/[email protected]
Jul 1 01:15:47: VERIFY OK: depth=0, /C=CH/ST=ZH/O=Monzoon_Networks_AG/OU=OpenVPN_server/CN=server/[email protected]
Jul 1 01:15:50: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 1 01:15:50: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 1 01:15:50: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 1 01:15:50: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 1 01:15:50: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
Jul 1 01:15:50: [server] Peer Connection Initiated with 80.254.79.101:443
Jul 1 01:15:51: MANAGEMENT: >STATE:1372677352,GET_CONFIG,,,
Jul 1 01:15:52: SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Jul 1 01:15:53: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 80.254.79.157,dhcp-option DNS 80.254.77.39,route-gateway 93.94.245.1,topology subnet,ping 10,ping-restart 60,socket-flags TCP_NODELAY,ifconfig 93.94.245.14 255.255.255.128'
Jul 1 01:15:53: OPTIONS IMPORT: timers and/or timeouts modified
Jul 1 01:15:53: OPTIONS IMPORT: --socket-flags option modified
Jul 1 01:15:53: Socket flags: TCP_NODELAY=1 succeeded
Jul 1 01:15:53: OPTIONS IMPORT: --ifconfig/up options modified
Jul 1 01:15:53: OPTIONS IMPORT: route options modified
Jul 1 01:15:53: OPTIONS IMPORT: route-related options modified
Jul 1 01:15:53: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Jul 1 01:15:53: ROUTE default_gateway=192.10.200.250
Jul 1 01:15:53: MANAGEMENT: >STATE:1372677354,ASSIGN_IP,,93.94.245.14,
Jul 1 01:15:53: TAP-WIN32 device [SwissVPN] opened: \\.\Global\{E13C1EAF-4BF2-4528-98EB-87CA45DCC0B8}.tap
Jul 1 01:15:53: TAP-Win32 Driver Version 9.9 
Jul 1 01:15:53: TAP-Win32 MTU=1500
Jul 1 01:15:53: Set TAP-Win32 TUN subnet mode network/local/netmask = 93.94.245.0/93.94.245.14/255.255.255.128 [SUCCEEDED]
Jul 1 01:15:53: Notified TAP-Win32 driver to set a DHCP IP/netmask of 93.94.245.14/255.255.255.128 on interface {E13C1EAF-4BF2-4528-98EB-87CA45DCC0B8} [DHCP-serv: 93.94.245.126, lease-time: 31536000]
Jul 1 01:15:53: DHCP option string: 060850fe 4f9d50fe 4d27
Jul 1 01:15:53: Successful ARP Flush on interface [16] {E13C1EAF-4BF2-4528-98EB-87CA45DCC0B8}
Jul 1 01:15:58: TEST ROUTES: 6/6 succeeded len=5 ret=1 a=0 u/d=up
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 80.254.79.101 MASK 255.255.255.255 192.10.200.250
Jul 1 01:15:58: ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=10]
Jul 1 01:15:58: Route addition via IPAPI failed [adaptive]
Jul 1 01:15:58: Route addition fallback to route.exe
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 0.0.0.0 MASK 128.0.0.0 93.94.245.1
Jul 1 01:15:58: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=30 and dwForwardType=4
Jul 1 01:15:58: Route addition via IPAPI succeeded [adaptive]
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 128.0.0.0 MASK 128.0.0.0 93.94.245.1
Jul 1 01:15:58: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=30 and dwForwardType=4
Jul 1 01:15:58: Route addition via IPAPI succeeded [adaptive]
Jul 1 01:15:58: MANAGEMENT: >STATE:1372677359,ADD_ROUTES,,,
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 69.80.120.35 MASK 255.255.255.255 192.10.200.250
Jul 1 01:15:58: ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=10]
Jul 1 01:15:58: Route addition via IPAPI failed [adaptive]
Jul 1 01:15:58: Route addition fallback to route.exe
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 38.97.75.94 MASK 255.255.255.255 192.10.200.250
Jul 1 01:15:58: ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=10]
Jul 1 01:15:58: Route addition via IPAPI failed [adaptive]
Jul 1 01:15:58: Route addition fallback to route.exe
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 108.160.162.113 MASK 255.255.255.255 192.10.200.250
Jul 1 01:15:58: ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=10]
Jul 1 01:15:58: Route addition via IPAPI failed [adaptive]
Jul 1 01:15:58: Route addition fallback to route.exe
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 199.47.217.177 MASK 255.255.255.255 192.10.200.250
Jul 1 01:15:58: ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=10]
Jul 1 01:15:58: Route addition via IPAPI failed [adaptive]
Jul 1 01:15:58: Route addition fallback to route.exe
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 184.73.211.238 MASK 255.255.255.255 192.10.200.250
Jul 1 01:15:58: ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=10]
Jul 1 01:15:58: Route addition via IPAPI failed [adaptive]
Jul 1 01:15:58: Route addition fallback to route.exe
Jul 1 01:15:58: Initialization Sequence Completed
Jul 1 01:15:58: MANAGEMENT: >STATE:1372677359,CONNECTED,SUCCESS,93.94.245.14,80.254.79.101
Jul 01 01:15:59: State changed to Connected
Jul 1 01:16:00: MANAGEMENT: CMD 'status'
Jul 1 01:16:01: MANAGEMENT: CMD 'status'
Jul 1 01:16:02: MANAGEMENT: CMD 'status'
Jul 1 01:16:03: MANAGEMENT: CMD 'status'
Jul 1 01:16:04: MANAGEMENT: CMD 'status'
Jul 1 01:16:05: MANAGEMENT: CMD 'status'
Jul 1 01:16:06: MANAGEMENT: CMD 'status'
Jul 1 01:16:07: MANAGEMENT: CMD 'status'
Jul 1 01:16:08: MANAGEMENT: CMD 'status'
Jul 1 01:16:09: MANAGEMENT: CMD 'status'
Jul 01 01:15:40: State changed to Connecting
Jul 01 01:15:40: Viscosity 1.4.4 (1191)
Jul 01 01:15:40: Running on Microsoft Windows 7 Home Premium 
Jul 01 01:15:41: Bringing up interface...
Jul 01 01:15:41: Checking reachability status of connection...
Jul 01 01:15:41: Connection is reachable. Starting connection attempt.
Jul 01 01:15:42: 52160 Mon Jul 01 13:15:42 2013 us=515000 Current Parameter Settings:
Jul 1 01:15:42: MANAGEMENT: CMD 'state on'
Jul 1 01:15:42: MANAGEMENT: CMD ''
Jul 1 01:15:42: MANAGEMENT: CMD 'hold release'
Jul 1 01:15:42: MANAGEMENT: CMD ''
Jul 1 01:15:42: MANAGEMENT: CMD 'username "Auth" "bgtspuzb"'
Jul 1 01:15:42: MANAGEMENT: CMD 'password [...]'
Jul 1 01:15:42: MANAGEMENT: CMD ''
Jul 1 01:15:43: WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Jul 1 01:15:43: NOTE: OpenVPN 2.1 requires '--script-security 2' or higher to call user-defined scripts or executables
Jul 1 01:15:43: Control Channel MTU parms [ L:1543 D:140 EF:40 EB:0 ET:0 EL:0 ]
Jul 1 01:15:43: Socket Buffers: R=[8192->8192] S=[8192->8192]
Jul 1 01:15:43: MANAGEMENT: >STATE:1372677343,RESOLVE,,,
Jul 1 01:15:43: RESOLVE: NOTE: connect-openvpn.swissvpn.net resolves to 3 addresses
Jul 1 01:15:43: Data Channel MTU parms [ L:1543 D:1450 EF:43 EB:4 ET:0 EL:0 ]
Jul 1 01:15:43: Local Options String: 'V4,dev-type tun,link-mtu 1543,tun-mtu 1500,proto TCPv4_CLIENT,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Jul 1 01:15:43: Expected Remote Options String: 'V4,dev-type tun,link-mtu 1543,tun-mtu 1500,proto TCPv4_SERVER,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Jul 1 01:15:43: Local Options hash (VER=V4): 'db02a8f8'
Jul 1 01:15:43: Expected Remote Options hash (VER=V4): '7e068940'
Jul 1 01:15:43: Attempting to establish TCP connection with 80.254.79.101:443
Jul 1 01:15:43: MANAGEMENT: >STATE:1372677343,TCP_CONNECT,,,
Jul 1 01:15:43: TCP connection established with 80.254.79.101:443
Jul 1 01:15:43: TCPv4_CLIENT link local: [undef]
Jul 1 01:15:43: TCPv4_CLIENT link remote: 80.254.79.101:443
Jul 1 01:15:43: MANAGEMENT: >STATE:1372677343,WAIT,,,
Jul 1 01:15:43: MANAGEMENT: >STATE:1372677344,AUTH,,,
Jul 1 01:15:43: TLS: Initial packet from 80.254.79.101:443, sid=f2c94e3b becb3309
Jul 1 01:15:43: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Jul 1 01:15:47: VERIFY OK: depth=1, /C=CH/ST=ZH/L=Regensdorf/O=Monzoon_Networks_AG/OU=OpenVPN_CA/CN=OpenVPN-CA/[email protected]
Jul 1 01:15:47: VERIFY OK: depth=0, /C=CH/ST=ZH/O=Monzoon_Networks_AG/OU=OpenVPN_server/CN=server/[email protected]
Jul 1 01:15:50: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 1 01:15:50: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 1 01:15:50: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 1 01:15:50: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 1 01:15:50: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
Jul 1 01:15:50: [server] Peer Connection Initiated with 80.254.79.101:443
Jul 1 01:15:51: MANAGEMENT: >STATE:1372677352,GET_CONFIG,,,
Jul 1 01:15:52: SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Jul 1 01:15:53: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 80.254.79.157,dhcp-option DNS 80.254.77.39,route-gateway 93.94.245.1,topology subnet,ping 10,ping-restart 60,socket-flags TCP_NODELAY,ifconfig 93.94.245.14 255.255.255.128'
Jul 1 01:15:53: OPTIONS IMPORT: timers and/or timeouts modified
Jul 1 01:15:53: OPTIONS IMPORT: --socket-flags option modified
Jul 1 01:15:53: Socket flags: TCP_NODELAY=1 succeeded
Jul 1 01:15:53: OPTIONS IMPORT: --ifconfig/up options modified
Jul 1 01:15:53: OPTIONS IMPORT: route options modified
Jul 1 01:15:53: OPTIONS IMPORT: route-related options modified
Jul 1 01:15:53: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Jul 1 01:15:53: ROUTE default_gateway=192.10.200.250
Jul 1 01:15:53: MANAGEMENT: >STATE:1372677354,ASSIGN_IP,,93.94.245.14,
Jul 1 01:15:53: TAP-WIN32 device [SwissVPN] opened: \\.\Global\{E13C1EAF-4BF2-4528-98EB-87CA45DCC0B8}.tap
Jul 1 01:15:53: TAP-Win32 Driver Version 9.9 
Jul 1 01:15:53: TAP-Win32 MTU=1500
Jul 1 01:15:53: Set TAP-Win32 TUN subnet mode network/local/netmask = 93.94.245.0/93.94.245.14/255.255.255.128 [SUCCEEDED]
Jul 1 01:15:53: Notified TAP-Win32 driver to set a DHCP IP/netmask of 93.94.245.14/255.255.255.128 on interface {E13C1EAF-4BF2-4528-98EB-87CA45DCC0B8} [DHCP-serv: 93.94.245.126, lease-time: 31536000]
Jul 1 01:15:53: DHCP option string: 060850fe 4f9d50fe 4d27
Jul 1 01:15:53: Successful ARP Flush on interface [16] {E13C1EAF-4BF2-4528-98EB-87CA45DCC0B8}
Jul 1 01:15:58: TEST ROUTES: 6/6 succeeded len=5 ret=1 a=0 u/d=up
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 80.254.79.101 MASK 255.255.255.255 192.10.200.250
Jul 1 01:15:58: ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=10]
Jul 1 01:15:58: Route addition via IPAPI failed [adaptive]
Jul 1 01:15:58: Route addition fallback to route.exe
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 0.0.0.0 MASK 128.0.0.0 93.94.245.1
Jul 1 01:15:58: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=30 and dwForwardType=4
Jul 1 01:15:58: Route addition via IPAPI succeeded [adaptive]
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 128.0.0.0 MASK 128.0.0.0 93.94.245.1
Jul 1 01:15:58: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=30 and dwForwardType=4
Jul 1 01:15:58: Route addition via IPAPI succeeded [adaptive]
Jul 1 01:15:58: MANAGEMENT: >STATE:1372677359,ADD_ROUTES,,,
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 69.80.120.35 MASK 255.255.255.255 192.10.200.250
Jul 1 01:15:58: ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=10]
Jul 1 01:15:58: Route addition via IPAPI failed [adaptive]
Jul 1 01:15:58: Route addition fallback to route.exe
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 38.97.75.94 MASK 255.255.255.255 192.10.200.250
Jul 1 01:15:58: ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=10]
Jul 1 01:15:58: Route addition via IPAPI failed [adaptive]
Jul 1 01:15:58: Route addition fallback to route.exe
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 108.160.162.113 MASK 255.255.255.255 192.10.200.250
Jul 1 01:15:58: ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=10]
Jul 1 01:15:58: Route addition via IPAPI failed [adaptive]
Jul 1 01:15:58: Route addition fallback to route.exe
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 199.47.217.177 MASK 255.255.255.255 192.10.200.250
Jul 1 01:15:58: ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=10]
Jul 1 01:15:58: Route addition via IPAPI failed [adaptive]
Jul 1 01:15:58: Route addition fallback to route.exe
Jul 1 01:15:58: C:\WINDOWS\system32\route.exe ADD 184.73.211.238 MASK 255.255.255.255 192.10.200.250
Jul 1 01:15:58: ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=10]
Jul 1 01:15:58: Route addition via IPAPI failed [adaptive]
Jul 1 01:15:58: Route addition fallback to route.exe
Jul 1 01:15:58: Initialization Sequence Completed
Jul 1 01:15:58: MANAGEMENT: >STATE:1372677359,CONNECTED,SUCCESS,93.94.245.14,80.254.79.101
Jul 01 01:15:59: State changed to Connected
Jul 1 01:16:00: MANAGEMENT: CMD 'status'
Jul 1 01:16:01: MANAGEMENT: CMD 'status'
Jul 1 01:16:02: MANAGEMENT: CMD 'status'
Jul 1 01:16:03: MANAGEMENT: CMD 'status'
(snip)
Jul 1 01:17:24: MANAGEMENT: CMD 'status'
Jul 1 01:17:25: MANAGEMENT: CMD 'status'
Jul 1 01:17:26: MANAGEMENT: CMD 'status'
Jul 1 01:17:27: MANAGEMENT: CMD 'status'
Jul 01 01:25:29: State changed to Disconnecting
I selected "Disconnect" after the connection appeared to lock up (ping no longer responding) but was unable to connect again, even though "Connect to SwissVPN" was a menu option. It just didn't do anything. I had to exit viscosity completely.

I will try again later.
Donn Edwards
Johannesburg, South Africa

DonnEdwards

Posts: 10
Joined: Fri Jun 28, 2013 7:00 pm

Post by DonnEdwards » Tue Jul 02, 2013 2:06 am
This is getting weird.
Code: Select all
Jul 01 05:15:28: State changed to Connecting
Jul 01 05:15:29: Viscosity 1.4.4 (1191)
Jul 01 05:15:29: Running on Microsoft Windows 7 Home Premium 
Jul 01 05:15:29: Bringing up interface...
Jul 01 05:15:29: Checking reachability status of connection...Jul 01 05:15:31: Connection is reachable. Starting connection attempt.
Jul 01 05:15:32: 49235 Mon Jul 01 17:15:32 2013 us=765000 Current Parameter Settings:
Jul 1 05:15:33: MANAGEMENT: CMD 'state on'
Jul 1 05:15:33: MANAGEMENT: CMD ''
Jul 1 05:15:33: MANAGEMENT: CMD 'hold release'
Jul 1 05:15:33: MANAGEMENT: CMD ''
Jul 1 05:15:33: MANAGEMENT: CMD 'username "Auth" "bgtspuzb"'
Jul 1 05:15:33: MANAGEMENT: CMD 'password [...]'
Jul 1 05:15:33: MANAGEMENT: CMD ''
Jul 1 05:15:34: WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Jul 1 05:15:34: NOTE: OpenVPN 2.1 requires '--script-security 2' or higher to call user-defined scripts or executables
Jul 1 05:15:34: Control Channel MTU parms [ L:1543 D:140 EF:40 EB:0 ET:0 EL:0 ]
Jul 1 05:15:34: Socket Buffers: R=[8192->8192] S=[8192->8192]
Jul 1 05:15:34: MANAGEMENT: >STATE:1372691734,RESOLVE,,,
Jul 1 05:15:34: RESOLVE: NOTE: connect-openvpn.swissvpn.net resolves to 3 addresses
Jul 1 05:15:34: Data Channel MTU parms [ L:1543 D:1450 EF:43 EB:4 ET:0 EL:0 ]
Jul 1 05:15:34: Local Options String: 'V4,dev-type tun,link-mtu 1543,tun-mtu 1500,proto TCPv4_CLIENT,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Jul 1 05:15:34: Expected Remote Options String: 'V4,dev-type tun,link-mtu 1543,tun-mtu 1500,proto TCPv4_SERVER,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Jul 1 05:15:34: Local Options hash (VER=V4): 'db02a8f8'
Jul 1 05:15:34: Expected Remote Options hash (VER=V4): '7e068940'
Jul 1 05:15:34: Attempting to establish TCP connection with 80.254.79.101:443
Jul 1 05:15:34: MANAGEMENT: >STATE:1372691735,TCP_CONNECT,,,
Jul 1 05:15:34: TCP connection established with 80.254.79.101:443
Jul 1 05:15:34: TCPv4_CLIENT link local: [undef]
Jul 1 05:15:34: TCPv4_CLIENT link remote: 80.254.79.101:443
Jul 1 05:15:34: MANAGEMENT: >STATE:1372691735,WAIT,,,
Jul 1 05:15:35: MANAGEMENT: >STATE:1372691735,AUTH,,,
Jul 1 05:15:35: TLS: Initial packet from 80.254.79.101:443, sid=51a5d384 c2b6e8ff
Jul 1 05:15:35: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Jul 1 05:15:40: VERIFY OK: depth=1, /C=CH/ST=ZH/L=Regensdorf/O=Monzoon_Networks_AG/OU=OpenVPN_CA/CN=OpenVPN-CA/[email protected]
Jul 1 05:15:40: VERIFY OK: depth=0, /C=CH/ST=ZH/O=Monzoon_Networks_AG/OU=OpenVPN_server/CN=server/[email protected]
Jul 1 05:15:44: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 1 05:15:44: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 1 05:15:44: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 1 05:15:44: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 1 05:15:44: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
Jul 1 05:15:44: [server] Peer Connection Initiated with 80.254.79.101:443
Jul 1 05:15:45: MANAGEMENT: >STATE:1372691746,GET_CONFIG,,,
Jul 1 05:15:46: SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Jul 1 05:15:47: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 80.254.79.157,dhcp-option DNS 80.254.77.39,route-gateway 93.94.245.1,topology subnet,ping 10,ping-restart 60,socket-flags TCP_NODELAY,ifconfig 93.94.245.98 255.255.255.128'
Jul 1 05:15:47: OPTIONS IMPORT: timers and/or timeouts modified
Jul 1 05:15:47: OPTIONS IMPORT: --socket-flags option modified
Jul 1 05:15:47: Socket flags: TCP_NODELAY=1 succeeded
Jul 1 05:15:47: OPTIONS IMPORT: --ifconfig/up options modified
Jul 1 05:15:47: OPTIONS IMPORT: route options modified
Jul 1 05:15:47: OPTIONS IMPORT: route-related options modified
Jul 1 05:15:47: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Jul 1 05:15:47: ROUTE default_gateway=192.10.200.250
Jul 1 05:15:47: MANAGEMENT: >STATE:1372691748,ASSIGN_IP,,93.94.245.98,
Jul 1 05:15:47: TAP-WIN32 device [SwissVPN] opened: \\.\Global\{E13C1EAF-4BF2-4528-98EB-87CA45DCC0B8}.tap
Jul 1 05:15:47: TAP-Win32 Driver Version 9.9 
Jul 1 05:15:47: TAP-Win32 MTU=1500
Jul 1 05:15:47: Set TAP-Win32 TUN subnet mode network/local/netmask = 93.94.245.0/93.94.245.98/255.255.255.128 [SUCCEEDED]
Jul 1 05:15:47: Notified TAP-Win32 driver to set a DHCP IP/netmask of 93.94.245.98/255.255.255.128 on interface {E13C1EAF-4BF2-4528-98EB-87CA45DCC0B8} [DHCP-serv: 93.94.245.126, lease-time: 31536000]
Jul 1 05:15:47: DHCP option string: 060850fe 4f9d50fe 4d27
Jul 1 05:15:47: Successful ARP Flush on interface [17] {E13C1EAF-4BF2-4528-98EB-87CA45DCC0B8}
Jul 1 05:15:52: TEST ROUTES: 6/6 succeeded len=5 ret=1 a=0 u/d=up
Jul 1 05:15:52: C:\WINDOWS\system32\route.exe ADD 80.254.79.101 MASK 255.255.255.255 192.10.200.250
Jul 1 05:15:52: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Jul 1 05:15:52: Route addition via IPAPI succeeded [adaptive]
Jul 1 05:15:52: C:\WINDOWS\system32\route.exe ADD 0.0.0.0 MASK 128.0.0.0 93.94.245.1
Jul 1 05:15:52: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=30 and dwForwardType=4
Jul 1 05:15:52: Route addition via IPAPI succeeded [adaptive]
Jul 1 05:15:52: C:\WINDOWS\system32\route.exe ADD 128.0.0.0 MASK 128.0.0.0 93.94.245.1
Jul 1 05:15:52: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=30 and dwForwardType=4
Jul 1 05:15:52: Route addition via IPAPI succeeded [adaptive]
Jul 1 05:15:52: MANAGEMENT: >STATE:1372691753,ADD_ROUTES,,,
Jul 1 05:15:52: C:\WINDOWS\system32\route.exe ADD 69.80.120.35 MASK 255.255.255.255 192.10.200.250
Jul 1 05:15:52: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Jul 1 05:15:52: Route addition via IPAPI succeeded [adaptive]
Jul 1 05:15:52: C:\WINDOWS\system32\route.exe ADD 38.97.75.94 MASK 255.255.255.255 192.10.200.250
Jul 1 05:15:52: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Jul 1 05:15:52: Route addition via IPAPI succeeded [adaptive]
Jul 1 05:15:52: C:\WINDOWS\system32\route.exe ADD 108.160.162.113 MASK 255.255.255.255 192.10.200.250
Jul 1 05:15:52: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Jul 1 05:15:52: Route addition via IPAPI succeeded [adaptive]
Jul 1 05:15:52: C:\WINDOWS\system32\route.exe ADD 199.47.217.177 MASK 255.255.255.255 192.10.200.250
Jul 1 05:15:52: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Jul 1 05:15:52: Route addition via IPAPI succeeded [adaptive]
Jul 1 05:15:52: C:\WINDOWS\system32\route.exe ADD 184.73.211.238 MASK 255.255.255.255 192.10.200.250
Jul 1 05:15:52: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Jul 1 05:15:52: Route addition via IPAPI succeeded [adaptive]
Jul 1 05:15:52: Initialization Sequence Completed
Jul 1 05:15:52: MANAGEMENT: >STATE:1372691753,CONNECTED,SUCCESS,93.94.245.98,80.254.79.101
Jul 01 05:15:52: State changed to Connected
Jul 1 05:15:53: MANAGEMENT: CMD 'status'
Jul 1 05:15:54: MANAGEMENT: CMD 'status'
Jul 1 05:15:55: MANAGEMENT: CMD 'status'
Jul 1 05:15:56: MANAGEMENT: CMD 'status'
Jul 1 05:15:57: MANAGEMENT: CMD 'status'
Jul 1 05:15:58: MANAGEMENT: CMD 'status'
Jul 1 05:15:59: MANAGEMENT: CMD 'status'
(snip)
Jul 1 05:44:30: MANAGEMENT: CMD 'status'
Jul 1 05:44:31: MANAGEMENT: CMD 'status'
Jul 1 05:44:32: MANAGEMENT: CMD 'status'
Jul 1 05:44:33: MANAGEMENT: CMD 'status'
Jul 1 05:44:34: MANAGEMENT: CMD 'status'
At this point the log stops, and no further traffic goes through the VPN. The status shows that the VPN is still connected, but the results of "ping -t 8.8.8.8" change from a normal response to "Response timed out"
I waited for another 5 minutes before disconnecting. Even the disconnect does not show on the log, so I quit Viscosity.

I have had feedback from the tech support guy at SwissVPN and he is also mystified. They don't have a policy of disconnecting users after any specific time.
Donn Edwards
Johannesburg, South Africa

Eric

User avatar
Posts: 1146
Joined: Sun Jan 03, 2010 3:27 am

Post by Eric » Tue Jul 02, 2013 11:08 am
Hi Donn,

Please try grabbing and installing the latest latest beta from here - http://www.sparklabs.com/forum/viewtopic.php?f=7&t=482

Once installed, force OpenVPN to 2.3 from the Advanced tab of Preferences and try to connect again. This will force to the latest version of OpenVPN you seem to be using 2.2 here which is quite old and could be the issue.

This message appearing quite often could also have an effect:

ROUTE: route addition failed using CreateIpForwardEntry: The object already exists. [status=5010 if_index=10]

If routes are not being added properly, this will be the reason for a reconnect failing (and could also be the cause of the drop outs). Please try connecting with no firewall or AV software running, as well as re-enabling any services you may have disabled.

Regards,

Eric
Eric Thorpe
Viscosity Developer

Web: http://www.sparklabs.com
Support: http://www.sparklabs.com/support
Twitter: http://twitter.com/sparklabs

DonnEdwards

Posts: 10
Joined: Fri Jun 28, 2013 7:00 pm

Post by DonnEdwards » Wed Jul 03, 2013 3:18 am
I forgot to disable the Firewall and AV (ESET Smart Security 6) but did trap the following in the Log. This is with the beta version 1.4.5 (1200). I'm not sure what happened to the top of the log
Code: Select all
Jul 2 05:59:10: MANAGEMENT: CMD 'status'
Jul 2 05:59:11: MANAGEMENT: CMD 'status'
Jul 2 05:59:12: MANAGEMENT: CMD 'status'
Jul 2 05:59:13: MANAGEMENT: CMD 'status'
Jul 2 05:59:14: MANAGEMENT: CMD 'status'
Jul 2 05:59:15: MANAGEMENT: CMD 'status'
(snip)
Jul 2 06:53:34: MANAGEMENT: CMD 'status'
Jul 2 06:53:35: MANAGEMENT: CMD 'status'
Jul 2 06:53:36: MANAGEMENT: CMD 'status'
Jul 2 06:53:37: MANAGEMENT: CMD 'status'
Jul 2 06:53:38: MANAGEMENT: CMD 'status'
Jul 2 06:53:39: MANAGEMENT: CMD 'status'
Jul 2 06:53:39: TLS: soft reset sec=0 bytes=118329868/0 pkts=141337/0
Jul 2 06:53:40: MANAGEMENT: CMD 'status'
Jul 2 06:53:41: VERIFY OK: depth=1, C=CH, ST=ZH, L=Regensdorf, O=Monzoon Networks AG, OU=OpenVPN CA, CN=OpenVPN-CA, [email protected]
Jul 2 06:53:41: VERIFY OK: depth=0, C=CH, ST=ZH, O=Monzoon Networks AG, OU=OpenVPN server, CN=server, [email protected]
Jul 2 06:53:41: MANAGEMENT: CMD 'status'
Jul 2 06:53:42: MANAGEMENT: CMD 'status'
Jul 2 06:53:43: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 2 06:53:43: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 2 06:53:43: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 2 06:53:43: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 2 06:53:43: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
Jul 2 06:53:43: MANAGEMENT: CMD 'status'
Jul 2 06:53:44: MANAGEMENT: CMD 'status'
Jul 2 06:53:45: MANAGEMENT: CMD 'status'
Jul 2 06:53:46: MANAGEMENT: CMD 'status'
Jul 2 06:53:47: MANAGEMENT: CMD 'status'
(snip)
Jul 2 06:56:31: MANAGEMENT: CMD 'status'
Jul 2 06:56:32: MANAGEMENT: CMD 'status'
Jul 2 06:56:33: MANAGEMENT: CMD 'status'
Jul 2 06:56:34: MANAGEMENT: CMD 'status'
Jul 2 06:56:35: MANAGEMENT: CMD 'status'
Jul 2 06:56:36: MANAGEMENT: CMD 'status'
Jul 2 06:56:37: MANAGEMENT: CMD 'status'
Jul 2 06:56:38: MANAGEMENT: CMD 'status'
Jul 2 06:56:39: Connection reset, restarting [0]
Jul 2 06:56:39: SIGUSR1[soft,connection-reset] received, process restarting
Jul 2 06:56:39: MANAGEMENT: >STATE:1372784199,RECONNECTING,connection-reset,,
Jul 02 06:56:39: State changed to Connecting
Jul 2 06:56:39: MANAGEMENT: CMD 'pid'
Jul 2 06:56:39: MANAGEMENT: CMD 'log on'
Jul 2 06:56:39: MANAGEMENT: CMD 'state on'
Jul 2 06:56:39: MANAGEMENT: CMD ''
Jul 2 06:56:39: MANAGEMENT: CMD 'hold release'
Jul 2 06:56:39: MANAGEMENT: CMD ''
Jul 2 06:57:03: MANAGEMENT: CMD 'status'
Jul 2 06:57:03: MANAGEMENT: CMD 'status'
Jul 2 06:57:03: MANAGEMENT: CMD 'status'
Jul 2 06:57:03: MANAGEMENT: CMD 'status'
Jul 2 06:57:03: MANAGEMENT: CMD 'status'
(etc)
Once the state changed to "Connecting" nothing further happened for at least 10 minutes. No traffic flowed, and no connection was ever established.

I hat to exit from Viscosity. On starting it again, I could connect:
Code: Select all
Jul 02 07:14:09: State changed to Connecting
Jul 02 07:14:09: Viscosity 1.4.5 (1200)
Jul 02 07:14:09: Running on Microsoft® Windows Vista™ Business 
Jul 02 07:14:09: Bringing up interface...
Jul 02 07:14:13: Checking reachability status of connection...
Jul 02 07:14:14: Connection is reachable. Starting connection attempt.
Jul 02 07:14:14: OpenVPN 2.3.2 Windows-MSVC [SSL (OpenSSL)] [LZO] [PKCS11] [eurephia] [IPv6] built on Jun  5 2013
Jul 2 07:14:15: MANAGEMENT: CMD 'state on'
Jul 2 07:14:15: MANAGEMENT: CMD ''
Jul 2 07:14:15: MANAGEMENT: CMD 'hold release'
Jul 2 07:14:15: MANAGEMENT: CMD ''
Jul 2 07:14:15: MANAGEMENT: CMD 'username "Auth" "bgtspuzb"'
Jul 2 07:14:15: MANAGEMENT: CMD 'password [...]'
Jul 2 07:14:15: MANAGEMENT: CMD ''
Jul 2 07:14:16: WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Jul 2 07:14:16: Socket Buffers: R=[8192->8192] S=[8192->8192]
Jul 2 07:14:16: MANAGEMENT: >STATE:1372785256,RESOLVE,,,
Jul 2 07:14:16: Attempting to establish TCP connection with [AF_INET]80.254.79.115:443 [nonblock]
Jul 2 07:14:16: MANAGEMENT: >STATE:1372785256,TCP_CONNECT,,,
Jul 2 07:14:17: TCP connection established with [AF_INET]80.254.79.115:443
Jul 2 07:14:17: TCPv4_CLIENT link local: [undef]
Jul 2 07:14:17: TCPv4_CLIENT link remote: [AF_INET]80.254.79.115:443
Jul 2 07:14:17: MANAGEMENT: >STATE:1372785257,WAIT,,,
Jul 2 07:14:17: MANAGEMENT: >STATE:1372785257,AUTH,,,
Jul 2 07:14:17: TLS: Initial packet from [AF_INET]80.254.79.115:443, sid=db77d4c5 729e4bcd
Jul 2 07:14:17: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Jul 2 07:14:21: VERIFY OK: depth=1, C=CH, ST=ZH, L=Regensdorf, O=Monzoon Networks AG, OU=OpenVPN CA, CN=OpenVPN-CA, [email protected]
Jul 2 07:14:21: VERIFY OK: depth=0, C=CH, ST=ZH, O=Monzoon Networks AG, OU=OpenVPN server, CN=server, [email protected]
Jul 2 07:14:24: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 2 07:14:24: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 2 07:14:24: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 2 07:14:24: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 2 07:14:24: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
Jul 2 07:14:24: [server] Peer Connection Initiated with [AF_INET]80.254.79.115:443
Jul 2 07:14:25: MANAGEMENT: >STATE:1372785265,GET_CONFIG,,,
Jul 2 07:14:26: SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Jul 2 07:14:27: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 80.254.79.157,dhcp-option DNS 80.254.77.39,route-gateway 109.205.170.1,topology subnet,ping 10,ping-restart 60,socket-flags TCP_NODELAY,ifconfig 109.205.170.39 255.255.255.128'
Jul 2 07:14:27: OPTIONS IMPORT: timers and/or timeouts modified
Jul 2 07:14:27: OPTIONS IMPORT: --socket-flags option modified
Jul 2 07:14:27: Socket flags: TCP_NODELAY=1 succeeded
Jul 2 07:14:27: OPTIONS IMPORT: --ifconfig/up options modified
Jul 2 07:14:27: OPTIONS IMPORT: route options modified
Jul 2 07:14:27: OPTIONS IMPORT: route-related options modified
Jul 2 07:14:27: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Jul 2 07:14:27: ROUTE_GATEWAY 192.10.10.250/255.255.255.0 I=10 HWADDR=00:1d:72:c7:93:34
Jul 2 07:14:27: do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
Jul 2 07:14:27: MANAGEMENT: >STATE:1372785267,ASSIGN_IP,,109.205.170.39,
Jul 2 07:14:27: open_tun, tt->ipv6=0
Jul 2 07:14:27: TAP-WIN32 device [SwissVPN] opened: \\.\Global\{1EE94F20-9634-402C-A461-5F38EB1E9286}.tap
Jul 2 07:14:27: TAP-Windows Driver Version 9.9 
Jul 2 07:14:27: Set TAP-Windows TUN subnet mode network/local/netmask = 109.205.170.0/109.205.170.39/255.255.255.128 [SUCCEEDED]
Jul 2 07:14:27: Notified TAP-Windows driver to set a DHCP IP/netmask of 109.205.170.39/255.255.255.128 on interface {1EE94F20-9634-402C-A461-5F38EB1E9286} [DHCP-serv: 109.205.170.126, lease-time: 31536000]
Jul 2 07:14:27: Successful ARP Flush on interface [107] {1EE94F20-9634-402C-A461-5F38EB1E9286}
Jul 2 07:14:32: TEST ROUTES: 8/8 succeeded len=7 ret=1 a=0 u/d=up
Jul 2 07:14:32: C:\Windows\system32\route.exe ADD 80.254.79.115 MASK 255.255.255.255 192.10.10.250
Jul 2 07:14:32: ROUTE: route addition failed using CreateIpForwardEntry: The object already exists.   [status=5010 if_index=10]
Jul 2 07:14:32: Route addition via IPAPI failed [adaptive]
Jul 2 07:14:32: Route addition fallback to route.exe
Jul 2 07:14:32: env_block: add PATH=C:\Windows\System32;C:\WINDOWS;C:\WINDOWS\System32\Wbem
Jul 2 07:14:32: C:\Windows\system32\route.exe ADD 0.0.0.0 MASK 128.0.0.0 109.205.170.1
Jul 2 07:14:32: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=30 and dwForwardType=4
Jul 2 07:14:32: Route addition via IPAPI succeeded [adaptive]
Jul 2 07:14:32: C:\Windows\system32\route.exe ADD 128.0.0.0 MASK 128.0.0.0 109.205.170.1
Jul 2 07:14:32: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=30 and dwForwardType=4
Jul 2 07:14:32: Route addition via IPAPI succeeded [adaptive]
Jul 2 07:14:32: MANAGEMENT: >STATE:1372785272,ADD_ROUTES,,,
Jul 2 07:14:32: C:\Windows\system32\route.exe ADD 196.28.0.0 MASK 255.255.0.0 192.10.10.250
Jul 2 07:14:32: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Jul 2 07:14:32: Route addition via IPAPI succeeded [adaptive]
Jul 2 07:14:32: C:\Windows\system32\route.exe ADD 69.80.120.35 MASK 255.255.255.255 192.10.10.250
Jul 2 07:14:32: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Jul 2 07:14:32: Route addition via IPAPI succeeded [adaptive]
Jul 2 07:14:32: C:\Windows\system32\route.exe ADD 108.160.162.113 MASK 255.255.255.255 192.10.10.250
Jul 2 07:14:32: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Jul 2 07:14:32: Route addition via IPAPI succeeded [adaptive]
Jul 2 07:14:32: C:\Windows\system32\route.exe ADD 184.73.211.238 MASK 255.255.255.255 192.10.10.250
Jul 2 07:14:32: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Jul 2 07:14:32: Route addition via IPAPI succeeded [adaptive]
Jul 2 07:14:32: C:\Windows\system32\route.exe ADD 199.47.216.178 MASK 255.255.255.255 192.10.10.250
Jul 2 07:14:32: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Jul 2 07:14:32: Route addition via IPAPI succeeded [adaptive]
Jul 2 07:14:32: C:\Windows\system32\route.exe ADD 199.47.217.177 MASK 255.255.255.255 192.10.10.250
Jul 2 07:14:32: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Jul 2 07:14:32: Route addition via IPAPI succeeded [adaptive]
Jul 2 07:14:32: C:\Windows\system32\route.exe ADD 38.97.75.0 MASK 255.255.255.0 192.10.10.250
Jul 2 07:14:32: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=20 and dwForwardType=4
Jul 2 07:14:32: Route addition via IPAPI succeeded [adaptive]
Jul 2 07:14:32: Initialization Sequence Completed
Jul 2 07:14:32: MANAGEMENT: >STATE:1372785272,CONNECTED,SUCCESS,109.205.170.39,80.254.79.115
Jul 02 07:14:32: State changed to Connected
Jul 2 07:14:33: MANAGEMENT: CMD 'status'
Jul 2 07:14:34: MANAGEMENT: CMD 'status'
Jul 2 07:14:35: MANAGEMENT: CMD 'status'
Jul 2 07:14:36: MANAGEMENT: CMD 'status'
Jul 2 07:14:37: MANAGEMENT: CMD 'status'
(etc)
I will try again with the Firewall and AV off.

BTW, version 1.4.5 has some nice UI improvements. \o/ \o/ \o/ Makes it easier to use when the preferences window is open.
Donn Edwards
Johannesburg, South Africa

DonnEdwards

Posts: 10
Joined: Fri Jun 28, 2013 7:00 pm

Post by DonnEdwards » Wed Jul 03, 2013 10:45 pm
Here is the result with AV and firewall turned off:
Code: Select all
Jul 03 11:12:05: State changed to Connecting
Jul 03 11:12:05: Viscosity 1.4.5 (1200)
Jul 03 11:12:05: Running on Microsoft® Windows Vista™ Business 
Jul 03 11:12:06: Bringing up interface...
Jul 03 11:12:10: Checking reachability status of connection...
Jul 03 11:12:12: Connection is reachable. Starting connection attempt.
Jul 03 11:12:12: OpenVPN 2.3.2 Windows-MSVC [SSL (OpenSSL)] [LZO] [PKCS11] [eurephia] [IPv6] built on Jun  5 2013
Jul 3 11:12:12: MANAGEMENT: CMD 'state on'
Jul 3 11:12:12: MANAGEMENT: CMD ''
Jul 3 11:12:12: MANAGEMENT: CMD 'hold release'
Jul 3 11:12:12: MANAGEMENT: CMD ''
Jul 3 11:12:12: MANAGEMENT: CMD 'username "Auth" "bgtspuzb"'
Jul 3 11:12:13: MANAGEMENT: CMD 'password [...]'
Jul 3 11:12:13: MANAGEMENT: CMD ''
Jul 3 11:12:13: WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
Jul 3 11:12:13: Socket Buffers: R=[8192->8192] S=[8192->8192]
Jul 3 11:12:13: MANAGEMENT: >STATE:1372842733,RESOLVE,,,
Jul 3 11:12:13: Attempting to establish TCP connection with [AF_INET]80.254.79.115:443 [nonblock]
Jul 3 11:12:13: MANAGEMENT: >STATE:1372842733,TCP_CONNECT,,,
Jul 3 11:12:14: TCP connection established with [AF_INET]80.254.79.115:443
Jul 3 11:12:14: TCPv4_CLIENT link local: [undef]
Jul 3 11:12:14: TCPv4_CLIENT link remote: [AF_INET]80.254.79.115:443
Jul 3 11:12:14: MANAGEMENT: >STATE:1372842734,WAIT,,,
Jul 3 11:12:15: MANAGEMENT: >STATE:1372842735,AUTH,,,
Jul 3 11:12:15: TLS: Initial packet from [AF_INET]80.254.79.115:443, sid=ef666132 dc494f61
Jul 3 11:12:15: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Jul 3 11:12:18: VERIFY OK: depth=1, C=CH, ST=ZH, L=Regensdorf, O=Monzoon Networks AG, OU=OpenVPN CA, CN=OpenVPN-CA, [email protected]
Jul 3 11:12:18: VERIFY OK: depth=0, C=CH, ST=ZH, O=Monzoon Networks AG, OU=OpenVPN server, CN=server, [email protected]
Jul 3 11:12:21: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 3 11:12:21: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 3 11:12:21: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 3 11:12:21: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 3 11:12:21: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
Jul 3 11:12:21: [server] Peer Connection Initiated with [AF_INET]80.254.79.115:443
Jul 3 11:12:22: MANAGEMENT: >STATE:1372842742,GET_CONFIG,,,
Jul 3 11:12:23: SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
Jul 3 11:12:23: PUSH: Received control message: 'PUSH_REPLY,redirect-gateway def1 bypass-dhcp,dhcp-option DNS 80.254.79.157,dhcp-option DNS 80.254.77.39,route-gateway 109.205.170.1,topology subnet,ping 10,ping-restart 60,socket-flags TCP_NODELAY,ifconfig 109.205.170.96 255.255.255.128'
Jul 3 11:12:23: OPTIONS IMPORT: timers and/or timeouts modified
Jul 3 11:12:23: OPTIONS IMPORT: --socket-flags option modified
Jul 3 11:12:23: Socket flags: TCP_NODELAY=1 succeeded
Jul 3 11:12:23: OPTIONS IMPORT: --ifconfig/up options modified
Jul 3 11:12:23: OPTIONS IMPORT: route options modified
Jul 3 11:12:23: OPTIONS IMPORT: route-related options modified
Jul 3 11:12:23: OPTIONS IMPORT: --ip-win32 and/or --dhcp-option options modified
Jul 3 11:12:23: ROUTE_GATEWAY 192.10.10.250/255.255.255.0 I=10 HWADDR=00:1d:72:c7:93:34
Jul 3 11:12:24: do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
Jul 3 11:12:24: MANAGEMENT: >STATE:1372842743,ASSIGN_IP,,109.205.170.96,
Jul 3 11:12:24: open_tun, tt->ipv6=0
Jul 3 11:12:24: TAP-WIN32 device [SwissVPN] opened: \\.\Global\{1EE94F20-9634-402C-A461-5F38EB1E9286}.tap
Jul 3 11:12:24: TAP-Windows Driver Version 9.9 
Jul 3 11:12:24: Set TAP-Windows TUN subnet mode network/local/netmask = 109.205.170.0/109.205.170.96/255.255.255.128 [SUCCEEDED]
Jul 3 11:12:24: Notified TAP-Windows driver to set a DHCP IP/netmask of 109.205.170.96/255.255.255.128 on interface {1EE94F20-9634-402C-A461-5F38EB1E9286} [DHCP-serv: 109.205.170.126, lease-time: 31536000]
Jul 3 11:12:24: Successful ARP Flush on interface [102] {1EE94F20-9634-402C-A461-5F38EB1E9286}Jul 3 11:12:28: TEST ROUTES: 8/8 succeeded len=7 ret=1 a=0 u/d=up
Jul 3 11:12:28: C:\Windows\system32\route.exe ADD 80.254.79.115 MASK 255.255.255.255 192.10.10.250
Jul 3 11:12:28: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=10 and dwForwardType=4
Jul 3 11:12:28: Route addition via IPAPI succeeded [adaptive]
Jul 3 11:12:28: C:\Windows\system32\route.exe ADD 0.0.0.0 MASK 128.0.0.0 109.205.170.1
Jul 3 11:12:28: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=30 and dwForwardType=4
Jul 3 11:12:28: Route addition via IPAPI succeeded [adaptive]
Jul 3 11:12:28: C:\Windows\system32\route.exe ADD 128.0.0.0 MASK 128.0.0.0 109.205.170.1
Jul 3 11:12:28: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=30 and dwForwardType=4
Jul 3 11:12:28: Route addition via IPAPI succeeded [adaptive]
Jul 3 11:12:28: MANAGEMENT: >STATE:1372842748,ADD_ROUTES,,,
Jul 3 11:12:28: C:\Windows\system32\route.exe ADD 196.28.0.0 MASK 255.255.0.0 192.10.10.250
Jul 3 11:12:28: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=10 and dwForwardType=4
Jul 3 11:12:28: Route addition via IPAPI succeeded [adaptive]
Jul 3 11:12:28: C:\Windows\system32\route.exe ADD 69.80.120.35 MASK 255.255.255.255 192.10.10.250
Jul 3 11:12:28: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=10 and dwForwardType=4
Jul 3 11:12:28: Route addition via IPAPI succeeded [adaptive]
Jul 3 11:12:28: C:\Windows\system32\route.exe ADD 108.160.162.113 MASK 255.255.255.255 192.10.10.250
Jul 3 11:12:28: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=10 and dwForwardType=4
Jul 3 11:12:28: Route addition via IPAPI succeeded [adaptive]
Jul 3 11:12:28: C:\Windows\system32\route.exe ADD 184.73.211.238 MASK 255.255.255.255 192.10.10.250
Jul 3 11:12:28: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=10 and dwForwardType=4
Jul 3 11:12:28: Route addition via IPAPI succeeded [adaptive]
Jul 3 11:12:28: C:\Windows\system32\route.exe ADD 199.47.216.178 MASK 255.255.255.255 192.10.10.250
Jul 3 11:12:28: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=10 and dwForwardType=4
Jul 3 11:12:28: Route addition via IPAPI succeeded [adaptive]
Jul 3 11:12:28: C:\Windows\system32\route.exe ADD 199.47.217.177 MASK 255.255.255.255 192.10.10.250
Jul 3 11:12:28: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=10 and dwForwardType=4
Jul 3 11:12:28: Route addition via IPAPI succeeded [adaptive]
Jul 3 11:12:28: C:\Windows\system32\route.exe ADD 38.97.75.0 MASK 255.255.255.0 192.10.10.250
Jul 3 11:12:28: ROUTE: CreateIpForwardEntry succeeded with dwForwardMetric1=10 and dwForwardType=4
Jul 3 11:12:28: Route addition via IPAPI succeeded [adaptive]
Jul 3 11:12:28: Initialization Sequence Completed
Jul 3 11:12:28: MANAGEMENT: >STATE:1372842748,CONNECTED,SUCCESS,109.205.170.96,80.254.79.115
Jul 03 11:12:28: State changed to Connected
Jul 3 11:12:29: MANAGEMENT: CMD 'status'
Jul 3 11:12:30: MANAGEMENT: CMD 'status'
Jul 3 11:12:31: MANAGEMENT: CMD 'status'
Jul 3 11:12:32: MANAGEMENT: CMD 'status'
(snip)
Jul 3 12:01:51: MANAGEMENT: CMD 'status'
Jul 3 12:01:52: MANAGEMENT: CMD 'status'
Jul 3 12:01:53: MANAGEMENT: CMD 'status'
Jul 3 12:01:54: MANAGEMENT: CMD 'status'
Jul 3 12:01:55: MANAGEMENT: CMD 'status'
Jul 3 12:01:55: Connection reset, restarting [-1]
Jul 3 12:01:55: SIGUSR1[soft,connection-reset] received, process restarting
Jul 3 12:01:55: MANAGEMENT: >STATE:1372845715,RECONNECTING,connection-reset,,
Jul 03 12:01:55: State changed to Connecting
Jul 3 12:01:55: MANAGEMENT: CMD 'pid'
Jul 3 12:01:55: MANAGEMENT: CMD 'log on'
Jul 3 12:01:55: MANAGEMENT: CMD 'state on'
Jul 3 12:01:55: MANAGEMENT: CMD ''
Jul 3 12:01:55: MANAGEMENT: CMD 'hold release'
Jul 3 12:01:55: MANAGEMENT: CMD ''
Jul 3 12:02:20: MANAGEMENT: CMD 'status'
Jul 3 12:02:20: MANAGEMENT: CMD 'status'
Jul 3 12:02:20: MANAGEMENT: CMD 'status'
Jul 3 12:02:20: MANAGEMENT: CMD 'status'
(etc)
This time it lasted only 50 minutes.

What bothers me more than the "connection reset" signal is that the "Reconnecting" status freezes up the entire network adapter, so that traffic excluded from the VPN (but not LAN traffic) is also stopped.

Clicking on the "Disconnect" button makes no difference :(

I guess this would have to be a new feature, but the option I would really like is "totally abandon the current connection, and start a new connection from scratch". Would such a feature be feasable?

Best wishes
Donn
Donn Edwards
Johannesburg, South Africa

Eric

User avatar
Posts: 1146
Joined: Sun Jan 03, 2010 3:27 am

Post by Eric » Thu Jul 04, 2013 11:39 am
Hi Donn,

I must have misunderstood you before, is pressing disconnect in Viscosity doing nothing? It will take 5-10 seconds for the disconnect to happen under this situation as there is a large amount of information being processed because of the high verb setting.

Have you rebooted your computer between these tests as there might be a couple of stray OpenVPN processes lingering that could even be causing this problem?

Are you able to send us a copy of your VPN configuration as exported from Viscosity (we don't need the certificates), as something is purposely blocking the pipe, there might be a bad route or ping command causing this. You're welcome to email it in if you do not wish it to be publicly visible. https://www.sparklabs.com/support/#contact

Regards,

Eric
Eric Thorpe
Viscosity Developer

Web: http://www.sparklabs.com
Support: http://www.sparklabs.com/support
Twitter: http://twitter.com/sparklabs
8 posts Page 1 of 1