no connection after upgrading to 1.3.1 / 1.3.0

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

hennesph

Posts: 1
Joined: Tue Jun 07, 2011 6:00 am

Post by hennesph » Tue Jun 07, 2011 6:09 am
Hi,

I updated viscosity to the latest version, since then then client does not connect to the openVPN server anymore.

Connection Log:
Jun 06 21:51:32: Viscosity 1.3.1 (1008)
Jun 06 21:51:32: Checking reachability status of connection...
Jun 06 21:51:32: Connection is reachable. Starting connection attempt.
Jun 06 21:51:35: OpenVPN 2.2.0 x86_64-apple-darwin10.7.0 [SSL] [LZO2] [PKCS11] [eurephia] built on May 11 2011
Jun 06 21:51:37: NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
Jun 06 21:51:37: LZO compression initialized
Jun 06 21:51:37: UDPv4 link local: [undef]
Jun 06 21:51:37: UDPv4 link remote: XX.XXX.XXX.XXX:1195
Jun 06 21:51:37: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
Jun 06 21:51:43: [olok-main-01] Peer Connection Initiated with XX.XXX.XXX.XXX:1195

In Viscosity I immediately after the last log entry get the message: Connection closed (translated from german ;-))

On the server side we use OpenVPN 2.1_rc11:
.....
user.name/XX.XXX.XXX.XX:62090 [user.name] Inactivity timeout
(--ping-restart), restarting
Jun 6 16:38:46 olok-main-01 ovpn-roadwarrior[3394]:
user.name/XX.XXX.XXX.XX:62090 SIGUSR1[soft,ping-restart] received,
client-instance restarting

Any tips?

Cheers
Philippe

James

User avatar
Posts: 1973
Joined: Thu Sep 04, 2008 9:27 pm

Post by James » Wed Jun 08, 2011 10:30 pm
Hi Philippe,

Would you be able to elaborate on the "Connection closed" message in German you are seeing? I'm afraid I'm not sure what message you could be referring to.

If you have "Use alternate DNS support" turned on in previous versions of Viscosity, are you able to connect if you turn on "Apply DNS settings simultaneously" under Preferences->Advanced?

Are there any messages from Viscosity or OpenVPN in the Console log?
http://www.thesparklabs.com/support/vie ... nsole_log/

Cheers,
James
James Bekkema
Viscosity Developer

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

ElGrowZone

Posts: 8
Joined: Thu Jun 30, 2011 10:32 pm

Post by ElGrowZone » Thu Jun 30, 2011 10:34 pm
I'm having the same problem. According to my VPN administrator, my Mac tries to open a second connection, which is not allowed. Is this any help?

I'm using 1.3.3 and tried changing almost all settings mentioned in posts about connection settings ;)

James

User avatar
Posts: 1973
Joined: Thu Sep 04, 2008 9:27 pm

Post by James » Thu Jun 30, 2011 10:40 pm
Hi ElGrowZone,
According to my VPN administrator, my Mac tries to open a second connection, which is not allowed. Is this any help?
Perhaps you have an OpenVPN process running in the background - have you tried restarting your computer?

Otherwise, you should check the OpenVPN log and see if it indicates what is happening.

Cheers,
James
James Bekkema
Viscosity Developer

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

ElGrowZone

Posts: 8
Joined: Thu Jun 30, 2011 10:32 pm

Post by ElGrowZone » Fri Jul 01, 2011 3:00 am
I have an (almost) exact same log as in the post above. According to the admin, a second session is started WHILE the first try isn't even fully connected!?!

ElGrowZone

Posts: 8
Joined: Thu Jun 30, 2011 10:32 pm

Post by ElGrowZone » Fri Jul 01, 2011 4:24 pm
Reboot didn't help :/

ElGrowZone

Posts: 8
Joined: Thu Jun 30, 2011 10:32 pm

Post by ElGrowZone » Mon Jul 04, 2011 5:55 pm
I'm getting the same server log entries as printed above. Any ideas on this?

James

User avatar
Posts: 1973
Joined: Thu Sep 04, 2008 9:27 pm

Post by James » Mon Jul 04, 2011 9:47 pm
Hi ElGrowZone,

The log snipped posted at the start of this thread is actually normal. Everyone should have something similar at the start of their log. What you need to look for is what comes after - it may hopefully indicate what is going on.

Assuming your IT guy is correct, it is impossible for Viscosity to launch two connection attempts from a single connection. If he is correct (he could be wrong - you may like to ask him for the log snippet to post here), it means that the extra connection attempt must be coming from something else. My suggestions would be:

1. If you are using custom Connected/Disconnected/BeforeConnect AppleScripts, make sure you aren't telling Viscosity to connect another connection in any of these.

2. If you are using software like MarcoPolo, HomeZone, etc. make sure it isn't telling Viscosity to initiate another connection.

3. If you have used other client software like Tunnelblick, make sure it doesn't have any background OpenVPN processes running (Tunnelblick is notorious for leaving OpenVPN processes around). You can check using the Activity Monitor (/Applications/Utilities/Activity Monitor.app) by selecting "All Processes" and do a search/filter for "openvpn".

4. Make sure someone else couldn't be using your credentials on another computer.

Cheers,
James
James Bekkema
Viscosity Developer

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

ElGrowZone

Posts: 8
Joined: Thu Jun 30, 2011 10:32 pm

Post by ElGrowZone » Tue Jul 05, 2011 5:21 am
Hi,

1. No.
2. No.
3. No - (btw. openvpn isn't 64 Bit? Not that I really care, but ... ;) )
4. No.

Here is the log: (no, I'm NOT working for Microsoft, maybe admins are having fun or something ...)

Jul 1 16:28:17 ovpn_srv openvpn[12561]: MULTI: multi_create_instance called
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 Re-using SSL/TLS context
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 LZO compression initialized
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 Local Options hash (VER=V4): '530fdded'
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 Expected Remote Options hash (VER=V4): '41690919'
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 TLS: Initial packet from 82.135.14.20:47754, sid=6550dc1e c5f22a37
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 CRL CHECK OK: /C=DE/ST=Bayern/L=Muenchen/O=Microsoft/OU=IT/CN=OpenVPN/emailAddress=[email protected]
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 VERIFY OK: depth=1, /C=DE/ST=Bayern/L=Muenchen/O=Microsoft/OU=IT/CN=OpenVPN/emailAddress=[email protected]
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 CRL CHECK OK: /CN=vmo/emailAddress=[email protected]/C=DE/L=Bayern/ST=Muenchen/O=Microsoft/OU=IT
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 VERIFY OK: depth=0, /CN=vmo/emailAddress=[email protected]/C=DE/L=Muenchen/ST=Bayern/O=Microsoft/OU=IT
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 1 16:28:17 ovpn_srv openvpn[12561]: 82.135.14.20:47754 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 1 16:28:18 ovpn_srv openvpn[12561]: 82.135.14.20:47754 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Jul 1 16:28:18 ovpn_srv openvpn[12561]: 82.135.14.20:47754 [vmo] Peer Connection Initiated with 82.135.14.20:47754
Jul 1 16:28:18 ovpn_srv openvpn[12561]: MULTI: new connection by client 'vmo' will cause previous active sessions by this client to be dropped. Remember to use the --duplicate-cn option if you want multiple clients using the same certificate or username to concurrently connect.
Jul 1 16:28:18 ovpn_srv openvpn[12561]: OPTIONS IMPORT: reading client specific options from: ccd/vmo
Jul 1 16:28:18 ovpn_srv openvpn[12561]: MULTI: Learn: 172.16.6.17 -> vmo/82.135.14.20:47754
Jul 1 16:28:18 ovpn_srv openvpn[12561]: MULTI: primary virtual IP for vmo/82.135.14.20:47754: 172.16.6.17
Jul 1 16:28:20 ovpn_srv openvpn[12561]: vmo/82.135.14.20:47754 PUSH: Received control message: 'PUSH_REQUEST'
Jul 1 16:28:20 ovpn_srv openvpn[12561]: vmo/82.135.14.20:47754 SENT CONTROL [vmo]: 'PUSH_REPLY,route 172.16.6.1,route 172.17.0.0 255.255.255.0,route 10.0.0.0 255.255.255.0,dhcp-option DNS 172.16.6.1,dhcp-option DOMAIN microsoft.de,ping 10,ping-restart 120,ifconfig 172.16.6.17 172.16.6.18' (status=1)
Jul 1 16:28:39 ovpn_srv openvpn[12561]: MANAGEMENT: Client connected from 8.8.8.8:23844
Jul 1 16:28:39 ovpn_srv openvpn[12561]: MANAGEMENT: Client disconnected
Jul 1 16:30:12 ovpn_srv openvpn[12662]: MANAGEMENT: Client connected from 8.8.8.8:23843
Jul 1 16:30:12 ovpn_srv openvpn[12662]: MANAGEMENT: Client disconnected
Jul 1 16:32:20 ovpn_srv openvpn[12561]: vmo/82.135.14.20:47754 [vmo] Inactivity timeout (--ping-restart), restarting
Jul 1 16:32:20 ovpn_srv openvpn[12561]: vmo/82.135.14.20:47754 SIGUSR1[soft,ping-restart] received, client-instance restarting
Jul 1 16:33:39 ovpn_srv openvpn[12561]: MANAGEMENT: Client connected from 8.8.8.8:23844
Jul 1 16:33:39 ovpn_srv openvpn[12561]: MANAGEMENT: Client disconnected
Jul 1 16:35:12 ovpn_srv openvpn[12662]: MANAGEMENT: Client connected from 8.8.8.8:23843
Jul 1 16:35:12 ovpn_srv openvpn[12662]: MANAGEMENT: Client disconnected
Jul 1 16:37:19 ovpn_srv openvpn[12561]: MULTI: multi_create_instance called
Jul 1 16:37:19 ovpn_srv openvpn[12561]: 82.135.14.20:37253 Re-using SSL/TLS context
Jul 1 16:37:19 ovpn_srv openvpn[12561]: 82.135.14.20:37253 LZO compression initialized
Jul 1 16:37:19 ovpn_srv openvpn[12561]: 82.135.14.20:37253 Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
Jul 1 16:37:19 ovpn_srv openvpn[12561]: 82.135.14.20:37253 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Jul 1 16:37:19 ovpn_srv openvpn[12561]: 82.135.14.20:37253 Local Options hash (VER=V4): '530fdded'
Jul 1 16:37:19 ovpn_srv openvpn[12561]: 82.135.14.20:37253 Expected Remote Options hash (VER=V4): '41690919'
Jul 1 16:37:19 ovpn_srv openvpn[12561]: 82.135.14.20:37253 TLS: Initial packet from 82.135.14.20:37253, sid=8f77eacc 749eae65
Jul 1 16:37:20 ovpn_srv openvpn[12561]: 82.135.14.20:37253 CRL CHECK OK: /C=DE/L=Muenchen/ST=Bayern/O=Microsoft/OU=IT/CN=OpenVPN/emailAddress=[email protected]
Jul 1 16:37:20 ovpn_srv openvpn[12561]: 82.135.14.20:37253 VERIFY OK: depth=1, /C=DE/L=Muenchen/ST=Bayern/O=Microsoft/OU=IT/CN=OpenVPN/emailAddress=[email protected]
Jul 1 16:37:20 ovpn_srv openvpn[12561]: 82.135.14.20:37253 CRL CHECK OK: /CN=vmo/emailAddress=[email protected]/C=DE/L=Muenchen/ST=Bayern/O=Microsoft/OU=IT
Jul 1 16:37:20 ovpn_srv openvpn[12561]: 82.135.14.20:37253 VERIFY OK: depth=0, /CN=vmo/emailAddress=[email protected]/C=DE/L=Muenchen/ST=Bayern/O=Microsoft/OU=IT
Jul 1 16:37:20 ovpn_srv openvpn[12561]: 82.135.14.20:37253 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 1 16:37:20 ovpn_srv openvpn[12561]: 82.135.14.20:37253 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 1 16:37:20 ovpn_srv openvpn[12561]: 82.135.14.20:37253 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Jul 1 16:37:20 ovpn_srv openvpn[12561]: 82.135.14.20:37253 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Jul 1 16:37:20 ovpn_srv openvpn[12561]: 82.135.14.20:37253 Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Jul 1 16:37:20 ovpn_srv openvpn[12561]: 82.135.14.20:37253 [vmo] Peer Connection Initiated with 82.135.14.20:37253
Jul 1 16:37:20 ovpn_srv openvpn[12561]: vmo/82.135.14.20:37253 OPTIONS IMPORT: reading client specific options from: ccd/vmo
Jul 1 16:37:20 ovpn_srv openvpn[12561]: vmo/82.135.14.20:37253 MULTI: Learn: 172.16.6.17 -> vmo/82.135.14.20:37253
Jul 1 16:37:20 ovpn_srv openvpn[12561]: vmo/82.135.14.20:37253 MULTI: primary virtual IP for vmo/82.135.14.20:37253: 172.16.6.17
Jul 1 16:37:22 ovpn_srv openvpn[12561]: vmo/82.135.14.20:37253 PUSH: Received control message: 'PUSH_REQUEST'
Jul 1 16:37:22 ovpn_srv openvpn[12561]: vmo/82.135.14.20:37253 SENT CONTROL [vmo]: 'PUSH_REPLY,route 172.16.6.1,route 172.17.0.0 255.255.255.0,route 10.0.0.0 255.255.255.0,dhcp-option DNS 172.16.6.1,dhcp-option DOMAIN microsoft.de,ping 10,ping-restart 120,ifconfig 172.16.6.17 172.16.6.18' (status=1)
Jul 1 16:38:39 ovpn_srv openvpn[12561]: MANAGEMENT: Client connected from 8.8.8.8:23844
Jul 1 16:38:39 ovpn_srv openvpn[12561]: MANAGEMENT: Client disconnected
Jul 1 16:40:12 ovpn_srv openvpn[12662]: MANAGEMENT: Client connected from 8.8.8.8:23843
Jul 1 16:40:12 ovpn_srv openvpn[12662]: MANAGEMENT: Client disconnected
Jul 1 16:41:22 ovpn_srv openvpn[12561]: vmo/82.135.14.20:37253 [vmo] Inactivity timeout (--ping-restart), restarting
Jul 1 16:41:22 ovpn_srv openvpn[12561]: vmo/82.135.14.20:37253 SIGUSR1[soft,ping-restart] received, client-instance restarting

James

User avatar
Posts: 1973
Joined: Thu Sep 04, 2008 9:27 pm

Post by James » Tue Jul 05, 2011 7:08 pm
Hi ElGrowZone,

You're going to need to post your OpenVPN log from Viscosity to see what is going on.

Here is what I think is happening based off those server logs:

1. Viscosity/OpenVPN connects to the server
2. It drops out for some reason (Viscosity's OpenVPN log should indicate why), and then tries to reconnect immediately
3. The first connection has not timed out on the server's end yet, so from the server's perspective it now looks like there are two active connections from the one user
4. The server terminates the second connection attempt

Cheers,
James
James Bekkema
Viscosity Developer

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