PKCS11/Yosemite doesn't work anymore

crashdump · 11 November 2014 11:01

Hi,

At first the connection seems to be establishing fine but it fails on the last steps (when setting up the routes and opening the tun interface): “do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0”:

Nov 11 10:43:46: Viscosity Mac 1.5.3b3 (1245)
Nov 11 10:43:46: Viscosity OpenVPN Engine Started
Nov 11 10:43:46: Running on Mac OS X 10.10
Nov 11 10:43:46: ---------
Nov 11 10:43:46: Checking reachability status of connection...
Nov 11 10:43:47: Connection is reachable. Starting connection attempt.
Nov 11 10:43:48: MANAGEMENT: CMD 'state on'
Nov 11 10:43:48: MANAGEMENT: CMD 'hold release'
Nov 11 10:43:48: PKCS#11: Adding PKCS#11 provider '/Library/OpenSC/lib/opensc-pkcs11.so'
Nov 11 10:43:48: PKCS#11: Adding PKCS#11 provider '/Library/OpenSC/lib/opensc-pkcs11.so'
Nov 11 10:43:49: LZO compression initialized
Nov 11 10:43:49: Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
Nov 11 10:43:49: Socket Buffers: R=[196724->65536] S=[9216->65536]
Nov 11 10:43:49: MANAGEMENT: >STATE:1415702629,RESOLVE,,,
Nov 11 10:43:49: Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Nov 11 10:43:49: Local Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Nov 11 10:43:49: Expected Remote Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Nov 11 10:43:49: Local Options hash (VER=V4): '41690919'
Nov 11 10:43:49: Expected Remote Options hash (VER=V4): '530fdded'
Nov 11 10:43:49: UDPv4 link local: [undef]
Nov 11 10:43:49: UDPv4 link remote: [AF_INET]5.5.5.5:1194
Nov 11 10:43:49: MANAGEMENT: >STATE:1415702629,WAIT,,,
Nov 11 10:43:49: MANAGEMENT: CMD 'hold release'
Nov 11 10:43:49: MANAGEMENT: >STATE:1415702629,AUTH,,,
Nov 11 10:43:49: TLS: Initial packet from [AF_INET]5.5.5.5:1194, sid=cf5ba635 b7d3c690
Nov 11 10:43:49: MANAGEMENT: CMD 'state on'
Nov 11 10:43:49: VERIFY OK: depth=1, CN=vpn.zzz.com
Nov 11 10:43:49: Validating certificate key usage
Nov 11 10:43:49: ++ Certificate has key usage  00a0, expects 00a0
Nov 11 10:43:49: VERIFY KU OK
Nov 11 10:43:49: Validating certificate extended key usage
Nov 11 10:43:49: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Nov 11 10:43:49: VERIFY EKU OK
Nov 11 10:43:49: VERIFY OK: depth=0, CN=vpn.zzz.com
Nov 11 10:43:49: MANAGEMENT: CMD 'hold release'
Nov 11 10:43:49: MANAGEMENT: CMD 'pid'
Nov 11 10:43:49: MANAGEMENT: CMD 'pid'
Nov 11 10:43:50: MANAGEMENT: CMD 'hold release'
Nov 11 10:43:50: MANAGEMENT: CMD 'pid'
Nov 11 10:43:50: MANAGEMENT: CMD 'pid'
Nov 11 10:43:52: MANAGEMENT: CMD 'password [...]'
Nov 11 10:43:53: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Nov 11 10:43:53: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Nov 11 10:43:53: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Nov 11 10:43:53: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Nov 11 10:43:53: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Nov 11 10:43:53: [vpn.zzz.com] Peer Connection Initiated with [AF_INET]5.5.5.5:1194
Nov 11 10:43:54: MANAGEMENT: >STATE:1415702634,GET_CONFIG,,,
Nov 11 10:43:55: SENT CONTROL [vpn.zzz.com]: 'PUSH_REQUEST' (status=1)
Nov 11 10:43:55: PUSH: Received control message: 'PUSH_REPLY,route 10.245.0.0 255.254.0.0,route 10.100.0.0 255.255.0.0,route 10.102.0.0 255.255.0.0,route 10.104.0.0 255.255.0.0,route 10.10.0.0 255.255.0.0,route 10.244.0.1,topology net30,ping 5,ping-restart 60,ifconfig 10.244.0.30 10.244.0.29'
Nov 11 10:43:55: OPTIONS IMPORT: timers and/or timeouts modified
Nov 11 10:43:55: OPTIONS IMPORT: --ifconfig/up options modified
Nov 11 10:43:55: OPTIONS IMPORT: route options modified
Nov 11 10:43:55: TUN/TAP device /dev/tun1 opened
Nov 11 10:43:55: do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
*stops here and disconnect*

Any idea what’s going on ?

Notes:

I am using the last revision of OpenSC (67fcda1, other PKCS11 tools are working on Yosemite).
I just updated Viscosity to 1.5.3b5 (1247), same result.

Cheers,

James · 11 November 2014 11:38

Hi crashdump,

I notice it is using an adapter of tun1 - this indicates tun0 is already in use. Could you have another connection connected at the same time, or stuck running in the background, that could be interfering with your new connection attempt? Try restarting your computer (simply killing the process using Activity Monitor may not be enough as DNS settings etc. might hang around) and see if you still run into the same problem.

The Adding PKCS#11 provider message is also appearing twice: try editing your connection in Viscosity and make sure you don’t have the same OpenSC provider file added twice, as this may cause issues.

Finally try checking the Console log for any errors or warnings from OpenVPN. Also check for system crash reports in case OpenVPN is crashing.
http://www.sparklabs.com/support/viewing_the_console_log/

Cheers,
James

crashdump · 11 November 2014 15:23

James,

[*] I had another (unrelated) VPN connection established (not a PKCS#11 one, just basic files-based certs) but the same problem occurs when I try this connection alone.

[*] I did have the same OpenSC provider file added twice, that’s now cleaned but it did not solve the problem.

[*] I tried to open Console when establishing a connection but did not see any logs from Viscosity or openvpn ?

Here’s the log from Viscosity itself:

Nov 11 15:07:45: Viscosity Mac 1.5.3b5 (1247)
Nov 11 15:07:45: Viscosity OpenVPN Engine Started
Nov 11 15:07:45: Running on Mac OS X 10.10
Nov 11 15:07:45: ---------
Nov 11 15:07:45: Checking reachability status of connection...
Nov 11 15:07:45: Connection is reachable. Starting connection attempt.
Nov 11 15:07:46: MANAGEMENT: CMD 'state on'
Nov 11 15:07:46: MANAGEMENT: CMD 'hold release'
Nov 11 15:07:46: PKCS#11: Adding PKCS#11 provider '/Library/OpenSC/lib/opensc-pkcs11.so'
Nov 11 15:07:47: LZO compression initialized
Nov 11 15:07:47: Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
Nov 11 15:07:47: Socket Buffers: R=[196724->65536] S=[9216->65536]
Nov 11 15:07:47: MANAGEMENT: >STATE:1415718467,RESOLVE,,,
Nov 11 15:07:47: Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Nov 11 15:07:47: Local Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-client'
Nov 11 15:07:47: Expected Remote Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128,key-method 2,tls-server'
Nov 11 15:07:47: Local Options hash (VER=V4): '41690919'
Nov 11 15:07:47: Expected Remote Options hash (VER=V4): '530fdded'
Nov 11 15:07:47: UDPv4 link local: [undef]
Nov 11 15:07:47: UDPv4 link remote: [AF_INET]5.5.5.5:1194
Nov 11 15:07:47: MANAGEMENT: >STATE:1415718467,WAIT,,,
Nov 11 15:07:47: MANAGEMENT: CMD 'hold release'
Nov 11 15:07:47: MANAGEMENT: >STATE:1415718467,AUTH,,,
Nov 11 15:07:47: TLS: Initial packet from [AF_INET]5.5.5.5:1194, sid=9e7ce1ba e9d74700
Nov 11 15:07:47: MANAGEMENT: CMD 'state on'
Nov 11 15:07:47: VERIFY OK: depth=1, CN=vpn.zzz.com
Nov 11 15:07:47: Validating certificate key usage
Nov 11 15:07:47: ++ Certificate has key usage  00a0, expects 00a0
Nov 11 15:07:47: VERIFY KU OK
Nov 11 15:07:47: Validating certificate extended key usage
Nov 11 15:07:47: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Nov 11 15:07:47: VERIFY EKU OK
Nov 11 15:07:47: VERIFY OK: depth=0, CN=vpn.zzz.com
Nov 11 15:07:48: MANAGEMENT: CMD 'hold release'
Nov 11 15:07:48: MANAGEMENT: CMD 'pid'
Nov 11 15:07:48: MANAGEMENT: CMD 'pid'
Nov 11 15:07:48: MANAGEMENT: CMD 'hold release'
Nov 11 15:07:48: MANAGEMENT: CMD 'pid'
Nov 11 15:07:48: MANAGEMENT: CMD 'pid'
Nov 11 15:07:50: MANAGEMENT: CMD 'password [...]'
Nov 11 15:07:51: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Nov 11 15:07:51: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Nov 11 15:07:51: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Nov 11 15:07:51: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Nov 11 15:07:51: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Nov 11 15:07:51: [vpn.zzz.com] Peer Connection Initiated with [AF_INET]5.5.5.5:1194
Nov 11 15:12:44: MANAGEMENT: >STATE:1415718764,GET_CONFIG,,,
Nov 11 15:12:46: SENT CONTROL [vpn.zzz.com]: 'PUSH_REQUEST' (status=1)
Nov 11 15:12:46: PUSH: Received control message: 'PUSH_REPLY,route 10.245.0.0 255.254.0.0,route 10.100.0.0 255.255.0.0,route 10.102.0.0 255.255.0.0,route 10.104.0.0 255.255.0.0,route 10.10.0.0 255.255.0.0,route 10.244.0.1,topology net30,ping 5,ping-restart 60,ifconfig 10.244.0.30 10.244.0.29'
Nov 11 15:12:46: OPTIONS IMPORT: timers and/or timeouts modified
Nov 11 15:12:46: OPTIONS IMPORT: --ifconfig/up options modified
Nov 11 15:12:46: OPTIONS IMPORT: route options modified
Nov 11 15:12:46: TUN/TAP device /dev/tun0 opened
Nov 11 15:12:46: do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
Nov 11 15:12:46: MANAGEMENT: >STATE:1415718766,ASSIGN_IP,,10.244.0.30,
Nov 11 15:12:46: /sbin/ifconfig tun0 delete
Nov 11 15:12:46: NOTE: Tried to delete pre-existing tun/tap instance -- No Problem if failure
Nov 11 15:12:46: /sbin/ifconfig tun0 10.244.0.30 10.244.0.29 mtu 1500 netmask 255.255.255.255 up
Nov 11 15:12:46: Mac OS X ifconfig failed: external program did not exit normally

Here is my OpenVPN config file:

#-- Config Auto Generated By Viscosity --#

#viscosity startonopen false
#viscosity dhcp true
#viscosity dnssupport false
#viscosity name vpn.zzz.com
remote vpn.zzz.com 1194 udp
pull
tls-client
persist-key
ca ca.crt
nobind
persist-tun
pkcs11-providers /Library/OpenSC/lib/opensc-pkcs11.so
comp-lzo adaptive
dev tun
pkcs11-id piv_II/PKCS\\x2315\\x20emulated/xxxxxxxx/PIV_II\\x20\\x28PIV\\x20Card\\x20Holder\\x20pin\\x29/02
remote-cert-tls server
verb 5

Thanks !

James · 11 November 2014 22:40

Hi crashdump,

The following command is likely the cause of what is going on:

Nov 11 15:12:46: /sbin/ifconfig tun0 10.244.0.30 10.244.0.29 mtu 1500 netmask 255.255.255.255 up
Nov 11 15:12:46: Mac OS X ifconfig failed: external program did not exit normally

If OpenVPN is failing to correctly set the IP address on the VPN adapter then that is probably the cause of the issue. Nothing stands out with the ifconfig command itself: I’d recommend you try running it manually in the Terminal immediately after OpenVPN tries and see what error message (if any) ifconfig prints out.

Cheers,
James

crashdump · 14 November 2014 15:31

Hi James,

I tried to establish the connection:

...
Nov 14 15:27:06: TUN/TAP device /dev/tun0 opened
Nov 14 15:27:06: do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
Nov 14 15:27:06: MANAGEMENT: >STATE:1415978826,ASSIGN_IP,,10.244.0.30,
Nov 14 15:27:06: /sbin/ifconfig tun0 delete
Nov 14 15:27:06: NOTE: Tried to delete pre-existing tun/tap instance -- No Problem if failure
Nov 14 15:27:06: /sbin/ifconfig tun0 10.244.0.30 10.244.0.29 mtu 1500 netmask 255.255.255.255 up
Nov 14 15:27:07: Mac OS X ifconfig failed: external program did not exit normally

And then cut & pasted the ifconfig command in a shell:

macbookpro:~$ /sbin/ifconfig tun0 10.244.0.30 10.244.0.29 mtu 1500 netmask 255.255.255.255 up
ifconfig: interface tun0 does not exist

Note: If I lookup for the tun0 interface when the connection is establishing, I can see it:

macbookpro:~$ ifconfig tun0
tun0: flags=8850<POINTOPOINT,RUNNING,SIMPLEX,MULTICAST> mtu 1500
	open (pid 10791)

Thanks,

James · 16 November 2014 09:35

Hi crashdump,

If you’re sure that the tun0 interface existed when you ran the ifconfig command, then it would suggest a serious networking issue on your machine. You could try updating to the latest beta version of Viscosity, which includes updated tun/tap drivers, however as there are no known issues with the current drivers on Yosemite I imagine you’ll unfortunately see the same result.

A few suggestions/comments:

Try updating to the latest beta version of Viscosity.
Could it be possible there is a tun driver loaded from another VPN client or network software that could be blocking Viscosity’s from loading correctly? You may like to try uninstalling any potentially conflicting software and then restarting your computer.
It’s possible there may be some sort of conflict in Mac OS X networking system. It may be worth resetting it by deleting the networking related plist files from /Library/SystemConfiguration/ and then restarting your computer.
Is it possible the interface IP address could somehow conflict with another address on your computer? If so, try turning off any additional network interfaces you don’t need, or change their IP range.
You mention that you do have another working connection: is it tun or tap based? My guess is it would be tap based, however if it is tun based it would indicate that the failure must be something specific to your connection rather than your whole computer. PKCS#11 shouldn’t interfere with networking setup, so it would have to be related to something else.
Reinstall Yosemite (yeah, this suggestion sucks, but if it is an OS issue it should solve it).

Cheers,
James

crashdump · 24 November 2014 10:32

Hi James,

So, I tried the “option 6” and on a freshly installed Yosemite with Viscosity 1.5.3b5 (I believe this is latest beta): There’s no more ifconfig problem but I still don’t get a connection.. It basically just disconnect after the last log entry ?

...
Nov 24 10:21:51: ++ Certificate has EKU (str) TLS Web Server Authentication, expects TLS Web Server Authentication
Nov 24 10:21:51: VERIFY EKU OK
Nov 24 10:21:51: VERIFY OK: depth=0, CN=vpn.zzz.com
Nov 24 10:21:51: MANAGEMENT: CMD 'state on'
Nov 24 10:21:52: MANAGEMENT: CMD 'hold release'
Nov 24 10:21:52: MANAGEMENT: CMD 'pid'
Nov 24 10:21:52: MANAGEMENT: CMD 'pid'
Nov 24 10:21:53: MANAGEMENT: CMD 'hold release'
Nov 24 10:21:53: MANAGEMENT: CMD 'pid'
Nov 24 10:21:53: MANAGEMENT: CMD 'pid'
Nov 24 10:21:55: MANAGEMENT: CMD 'password [...]'
Nov 24 10:21:56: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Nov 24 10:21:56: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Nov 24 10:21:56: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Nov 24 10:21:56: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Nov 24 10:21:56: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Nov 24 10:21:56: [vpn-prod.a2infra.com] Peer Connection Initiated with [AF_INET]5.5.5.5:1194
Nov 24 10:21:57: MANAGEMENT: >STATE:1416824517,GET_CONFIG,,,
Nov 24 10:21:58: SENT CONTROL [vpn.zzz.com]: 'PUSH_REQUEST' (status=1)
Nov 24 10:21:58: PUSH: Received control message: 'PUSH_REPLY,route 10.245.0.0 255.254.0.0,route 10.100.0.0 255.255.0.0,route 10.102.0.0 255.255.0.0,route 10.104.0.0 255.255.0.0,route 10.10.0.0 255.255.0.0,route 10.244.0.1,topology net30,ping 5,ping-restart 60,ifconfig 10.244.0.30 10.244.0.29'
Nov 24 10:21:58: OPTIONS IMPORT: timers and/or timeouts modified
Nov 24 10:21:58: OPTIONS IMPORT: --ifconfig/up options modified

Thanks,

James · 26 November 2014 06:29

Hi crashdump,

Do you still see OpenVPN failing in the same location when trying to make a raw OpenVPN connection in the Terminal (/Applications/Utilities/Terminal.app)? You can do this by typing the following commands into the Terminal (replace the number 1 with the correct folder number for your connection):

cd ~/Library/Application\ Support/Viscosity/OpenVPN/1/
sudo /Library/Application\ Support/Viscosity/openvpn config.conf

Cheers,
James

berne · 27 November 2014 07:42

I just posted a new thread. I have a similar issue. I am using the latest stable release, not the beta. I am stuck at ifconfig command failing due to openvpn crashing.

crashdump · 27 November 2014 10:00

James,

Yes – Even after a complete system reinstall (I did not restore from timemachine, I created a new account) I see the following:

$ sudo /Library/Application\ Support/Viscosity/openvpn config.conf
password:
Thu Nov 27 01:55:14 2014 OpenVPN 2.3.4 x86_64-apple-darwin [SSL (OpenSSL)] [LZO] [PKCS11] [MH] [IPv6] built on Oct 16 2014
Thu Nov 27 01:55:14 2014 library versions: OpenSSL 1.0.1j 15 Oct 2014, LZO 2.08
Thu Nov 27 01:55:14 2014 PKCS#11: Adding PKCS#11 provider '/usr/local/lib/opensc-pkcs11.so'
Thu Nov 27 01:55:15 2014 UDPv4 link local: [undef]
Thu Nov 27 01:55:15 2014 UDPv4 link remote: [AF_INET]5.5.5.5:1194
Enter PIV_II (PIV Card Holder pin) token Password:
Thu Nov 27 01:55:19 2014 [vpn.zzz.com] Peer Connection Initiated with [AF_INET]5.5.5.5:1194
Thu Nov 27 01:55:21 2014 Opened utun device utun0
Thu Nov 27 01:55:21 2014 do_ifconfig, tt->ipv6=0, tt->did_ifconfig_ipv6_setup=0
Thu Nov 27 01:55:21 2014 /sbin/ifconfig utun0 delete
Thu Nov 27 01:55:21 2014 NOTE: Tried to delete pre-existing tun/tap instance -- No Problem if failure
Thu Nov 27 01:55:21 2014 /sbin/ifconfig utun0 10.244.0.30 10.244.0.29 mtu 1500 netmask 255.255.255.255 up
Thu Nov 27 01:55:22 2014 Mac OS X ifconfig failed: external program did not exit normally
Thu Nov 27 01:55:22 2014 Exiting due to fatal error

I did not install any software which could interfere with the network (no other VPN client or Virtualisation software).

Running the ifconfig manually return the same error:

sudo /sbin/ifconfig utun0 10.244.0.30 10.244.0.29 mtu 1500 netmask 255.255.255.255 up
Password:
ifconfig: interface utun0 does not exist

Thanks,

James · 27 November 2014 13:14

Hi crashdump,

Berne’s post in the following thread sheds some more light on the problem. It looks like the ifconfig command failing is a false alarm in this case, and the problem actually lies with the OpenSC driver:
https://www.sparklabs.com/forum/t/openvpn-crashes-on-osx-10-10-yosemite/891/1

Cheers,
James