Viscosity 1.8.2 + OpenSC PKCS11

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

salt_of_the_moon

User avatar
Posts: 9
Joined: Sat May 27, 2017 8:09 am

Post by salt_of_the_moon » Tue Nov 19, 2019 4:11 am
Upon updating from Viscosity 1.7.14 to Viscosity 1.8.2 my VPN authentication "flow" appears to have broken.

Previously (v 1.7.14) the flow went something like this:
1. Select "Connect"
2. Username and password prompt appear.
3. Fill in username, leave password blank.
4. Authentication via PKCS11 (Yubikey)
5. Another prompt, this time for the Yubikey's PIN.
6. VPN connects.

Now (v 1.8.2) the flow goes more like this:
1. Select "Connect"
2. Username and password prompt appear.
3. Fill in username.
4. No prompt for PIN.
5. Prompt for username and password again. (loops forever)

I'm guessing something is wrong with the OpenSC/PKCS11 communications.

I'm on macOS Mojave 10.14.6
OpenSC version 0.17

salt_of_the_moon

User avatar
Posts: 9
Joined: Sat May 27, 2017 8:09 am

Post by salt_of_the_moon » Tue Nov 19, 2019 4:27 am
I tried updating to the latest version of OpenSC 0.19

Does not fix the issue.

James

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

Post by James » Tue Nov 19, 2019 9:53 am
Hi salt_of_the_moon,

I recommend checking the OpenVPN log for more information:
https://www.sparklabs.com/support/kb/ar ... envpn-log/

Cheers,
James
Web: https://www.sparklabs.com
Support: https://www.sparklabs.com/support
Twitter: https://twitter.com/sparklabs

salt_of_the_moon

User avatar
Posts: 9
Joined: Sat May 27, 2017 8:09 am

Post by salt_of_the_moon » Tue Dec 03, 2019 3:32 am
I just tried upgrading to 1.8.3 to see if that would change things.

While I do see some issues with the VPN configuration, I don't think that's the problem I'm encountering. For some reason after Viscosity reads the cert from the Yubikey, it just immediately goes to "disconnected".

Here are the logs from v1.7.14 (works) and the logs from v1.8.3 (doesn't work)

Version 1.7.14 Log
Code: Select all
2019-12-02 08:19:46: Viscosity Mac 1.7.14 (1480)
2019-12-02 08:19:46: Viscosity OpenVPN Engine Started
2019-12-02 08:19:46: Running on macOS 10.14.6
2019-12-02 08:19:46: ---------
2019-12-02 08:19:46: State changed to Connecting
2019-12-02 08:19:46: Checking reachability status of connection...
2019-12-02 08:19:46: Connection is reachable. Starting connection attempt.
2019-12-02 08:19:46: OpenVPN 2.4.6 x86_64-apple-darwin [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [MH/RECVDA] [AEAD] built on Nov 23 2018
2019-12-02 08:19:46: library versions: OpenSSL 1.0.2q  20 Nov 2018, LZO 2.10
2019-12-02 08:19:47: PKCS#11: Adding PKCS#11 provider '/Library/OpenSC/lib/opensc-pkcs11.so'
2019-12-02 08:19:47: WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
2019-12-02 08:19:47: TCP/UDP: Preserving recently used remote address: [AF_INET]X.X.X.X:1194
2019-12-02 08:19:47: UDP link local: (not bound)
2019-12-02 08:19:47: UDP link remote: [AF_INET]X.X.X.X:1194
2019-12-02 08:19:47: State changed to Authenticating
2019-12-02 08:19:47: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
2019-12-02 08:19:48: [vpn.company.com] Peer Connection Initiated with [AF_INET]X.X.X.X:1194
2019-12-02 08:20:04: Opened utun device utun10
2019-12-02 08:20:04: do_ifconfig, tt->did_ifconfig_ipv6_setup=0
2019-12-02 08:20:04: /sbin/ifconfig utun10 delete
2019-12-02 08:20:04: NOTE: Tried to delete pre-existing tun/tap instance -- No Problem if failure
2019-12-02 08:20:04: /sbin/ifconfig utun10 10.222.0.5 10.222.0.5 netmask 255.255.255.0 mtu 1500 up
2019-12-02 08:20:04: Initialization Sequence Completed
2019-12-02 08:20:04: DNS mode set to Split
2019-12-02 08:20:05: State changed to Connected

Version 1.8.3 Log
Code: Select all
2019-12-02 08:14:39: Viscosity Mac 1.8.3 (1521)
2019-12-02 08:14:39: Viscosity OpenVPN Engine Started
2019-12-02 08:14:39: Running on macOS 10.14.6
2019-12-02 08:14:39: ---------
2019-12-02 08:14:39: State changed to Connecting
2019-12-02 08:14:39: Checking reachability status of connection...
2019-12-02 08:14:39: Connection is reachable. Starting connection attempt.
2019-12-02 08:14:39: OpenVPN 2.4.8 x86_64-apple-darwin [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [MH/RECVDA] [AEAD] built on Nov 21 2019
2019-12-02 08:14:39: library versions: OpenSSL 1.1.1d  10 Sep 2019, LZO 2.10
2019-12-02 08:14:40: PKCS#11: Adding PKCS#11 provider '/Library/OpenSC/lib/opensc-pkcs11.so'
2019-12-02 08:14:40: Resolving address: vpn.company.com
2019-12-02 08:14:40: Resolving address: vpn.company.com
2019-12-02 08:14:40: Valid endpoint found: X.X.X.X:1194:udp
2019-12-02 08:14:40: WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
2019-12-02 08:14:40: TCP/UDP: Preserving recently used remote address: [AF_INET]X.X.X.X:1194
2019-12-02 08:14:40: UDP link local: (not bound)
2019-12-02 08:14:40: UDP link remote: [AF_INET]X.X.X.X:1194
2019-12-02 08:14:40: State changed to Authenticating
2019-12-02 08:14:40: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
2019-12-02 08:14:40: OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
2019-12-02 08:14:40: TLS_ERROR: BIO read tls_read_plaintext error
2019-12-02 08:14:40: TLS Error: TLS object -> incoming plaintext read error
2019-12-02 08:14:40: TLS Error: TLS handshake failed
2019-12-02 08:14:40: SIGTERM[soft,tls-error] received, process exiting
2019-12-02 08:14:40: State changed to Disconnected

James

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

Post by James » Tue Dec 03, 2019 12:10 pm
Hi salt_of_the_moon,

Thanks for posting your logs. It does appear OpenSSL is unhappy with the certificate/signature: it should be something we can find a solution to. Would you be able to increase the verbosity of the log, and post it here (or email it to us if you'd prefer not to have it publicly available)? That should give us a better idea of what is going on.

You can increase the log verbosity by adding the command "verb 7" (without the quotes) on a new line in the advanced commands section for your connection:
https://www.sparklabs.com/support/kb/article/advanced-configuration-commands/#specifying-advanced-configuration-commands

Cheers,
James
Web: https://www.sparklabs.com
Support: https://www.sparklabs.com/support
Twitter: https://twitter.com/sparklabs

salt_of_the_moon

User avatar
Posts: 9
Joined: Sat May 27, 2017 8:09 am

Post by salt_of_the_moon » Tue Dec 03, 2019 4:12 pm
Thanks James, here's the verbose log.
Code: Select all
2019-12-02 21:04:41: Viscosity Mac 1.8.3 (1521)
2019-12-02 21:04:41: Viscosity OpenVPN Engine Started
2019-12-02 21:04:41: Running on macOS 10.14.6
2019-12-02 21:04:41: ---------
2019-12-02 21:04:41: State changed to Connecting
2019-12-02 21:04:41: Checking reachability status of connection...
2019-12-02 21:04:41: Connection is reachable. Starting connection attempt.
2019-12-02 21:04:41: NOTE: debug verbosity (--verb 7) is enabled but this build lacks debug support.
2019-12-02 21:04:41: Current Parameter Settings:
2019-12-02 21:04:41:   config = 'config.conf'
2019-12-02 21:04:41:   mode = 0
2019-12-02 21:04:41:   show_ciphers = DISABLED
2019-12-02 21:04:41:   show_digests = DISABLED
2019-12-02 21:04:41:   show_engines = DISABLED
2019-12-02 21:04:41:   genkey = DISABLED
2019-12-02 21:04:41:   key_pass_file = '[UNDEF]'
2019-12-02 21:04:41:   show_tls_ciphers = DISABLED
2019-12-02 21:04:41:   connect_retry_max = 0
2019-12-02 21:04:41: Connection profiles [0]:
2019-12-02 21:04:41:   proto = udp
2019-12-02 21:04:41:   local = '[UNDEF]'
2019-12-02 21:04:41:   local_port = '[UNDEF]'
2019-12-02 21:04:41:   remote = 'vpn.company.com'
2019-12-02 21:04:41:   remote_port = '1194'
2019-12-02 21:04:41:   remote_float = DISABLED
2019-12-02 21:04:41:   bind_defined = DISABLED
2019-12-02 21:04:41:   bind_local = DISABLED
2019-12-02 21:04:41:   bind_ipv6_only = DISABLED
2019-12-02 21:04:41:   connect_retry_seconds = 5
2019-12-02 21:04:41:   connect_timeout = 120
2019-12-02 21:04:41:   socks_proxy_server = '[UNDEF]'
2019-12-02 21:04:41:   socks_proxy_port = '[UNDEF]'
2019-12-02 21:04:41:   tun_mtu = 1500
2019-12-02 21:04:41:   tun_mtu_defined = ENABLED
2019-12-02 21:04:41:   link_mtu = 1500
2019-12-02 21:04:41:   link_mtu_defined = DISABLED
2019-12-02 21:04:41:   tun_mtu_extra = 0
2019-12-02 21:04:41:   tun_mtu_extra_defined = DISABLED
2019-12-02 21:04:41:   mtu_discover_type = -1
2019-12-02 21:04:41:   fragment = 0
2019-12-02 21:04:41:   mssfix = 1450
2019-12-02 21:04:41:   explicit_exit_notification = 0
2019-12-02 21:04:41: Connection profiles END
2019-12-02 21:04:41:   remote_random = DISABLED
2019-12-02 21:04:41:   ipchange = '[UNDEF]'
2019-12-02 21:04:41:   dev = 'tun'
2019-12-02 21:04:41:   dev_type = '[UNDEF]'
2019-12-02 21:04:41:   dev_node = 'utun'
2019-12-02 21:04:41:   lladdr = '[UNDEF]'
2019-12-02 21:04:41:   topology = 1
2019-12-02 21:04:41:   ifconfig_local = '[UNDEF]'
2019-12-02 21:04:41:   ifconfig_remote_netmask = '[UNDEF]'
2019-12-02 21:04:41:   ifconfig_noexec = DISABLED
2019-12-02 21:04:41:   ifconfig_nowarn = DISABLED
2019-12-02 21:04:41:   ifconfig_ipv6_local = '[UNDEF]'
2019-12-02 21:04:41:   ifconfig_ipv6_netbits = 0
2019-12-02 21:04:41:   ifconfig_ipv6_remote = '[UNDEF]'
2019-12-02 21:04:41:   shaper = 0
2019-12-02 21:04:41:   mtu_test = 0
2019-12-02 21:04:41:   mlock = DISABLED
2019-12-02 21:04:41:   keepalive_ping = 10
2019-12-02 21:04:41:   keepalive_timeout = 120
2019-12-02 21:04:41:   inactivity_timeout = 0
2019-12-02 21:04:41:   ping_send_timeout = 10
2019-12-02 21:04:41:   ping_rec_timeout = 120
2019-12-02 21:04:41:   ping_rec_timeout_action = 2
2019-12-02 21:04:41:   ping_timer_remote = DISABLED
2019-12-02 21:04:41:   remap_sigusr1 = 0
2019-12-02 21:04:41:   persist_tun = DISABLED
2019-12-02 21:04:41:   persist_local_ip = DISABLED
2019-12-02 21:04:41:   persist_remote_ip = DISABLED
2019-12-02 21:04:41:   persist_key = DISABLED
2019-12-02 21:04:41:   passtos = DISABLED
2019-12-02 21:04:41:   resolve_retry_seconds = 1000000000
2019-12-02 21:04:41:   resolve_in_advance = DISABLED
2019-12-02 21:04:41:   username = '[UNDEF]'
2019-12-02 21:04:41:   groupname = '[UNDEF]'
2019-12-02 21:04:41:   chroot_dir = '[UNDEF]'
2019-12-02 21:04:41:   cd_dir = '[UNDEF]'
2019-12-02 21:04:41:   writepid = '[UNDEF]'
2019-12-02 21:04:41:   up_script = '[UNDEF]'
2019-12-02 21:04:41:   down_script = '[UNDEF]'
2019-12-02 21:04:41:   down_pre = DISABLED
2019-12-02 21:04:41:   up_restart = DISABLED
2019-12-02 21:04:41:   up_delay = DISABLED
2019-12-02 21:04:41:   daemon = DISABLED
2019-12-02 21:04:41:   inetd = 0
2019-12-02 21:04:41:   log = DISABLED
2019-12-02 21:04:41:   suppress_timestamps = DISABLED
2019-12-02 21:04:41:   machine_readable_output = DISABLED
2019-12-02 21:04:41:   nice = 0
2019-12-02 21:04:41:   verbosity = 7
2019-12-02 21:04:41:   mute = 100
2019-12-02 21:04:41:   status_file = '[UNDEF]'
2019-12-02 21:04:41:   status_file_version = 1
2019-12-02 21:04:41:   status_file_update_freq = 60
2019-12-02 21:04:41:   occ = ENABLED
2019-12-02 21:04:41:   rcvbuf = 0
2019-12-02 21:04:41:   sndbuf = 0
2019-12-02 21:04:41:   sockflags = 0
2019-12-02 21:04:41:   fast_io = DISABLED
2019-12-02 21:04:41:   comp.alg = 2
2019-12-02 21:04:41:   comp.flags = 1
2019-12-02 21:04:41:   route_script = '[UNDEF]'
2019-12-02 21:04:41:   route_default_gateway = '[UNDEF]'
2019-12-02 21:04:41:   route_default_metric = 0
2019-12-02 21:04:41:   route_noexec = DISABLED
2019-12-02 21:04:41:   route_delay = 0
2019-12-02 21:04:41: NOTE: --mute triggered...
2019-12-02 21:04:41: 181 variation(s) on previous 100 message(s) suppressed by --mute
2019-12-02 21:04:41: OpenVPN 2.4.8 x86_64-apple-darwin [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [MH/RECVDA] [AEAD] built on Nov 21 2019
2019-12-02 21:04:41: library versions: OpenSSL 1.1.1d  10 Sep 2019, LZO 2.10
2019-12-02 21:04:41: PKCS#11: Adding PKCS#11 provider '/Library/OpenSC/lib/opensc-pkcs11.so'
2019-12-02 21:04:41: PKCS#11: Adding provider '/Library/OpenSC/lib/opensc-pkcs11.so'-'/Library/OpenSC/lib/opensc-pkcs11.so'
2019-12-02 21:04:41: PKCS#11: Provider '/Library/OpenSC/lib/opensc-pkcs11.so' added rv=0-'CKR_OK'
2019-12-02 21:04:41: Resolving address: vpn.company.com
2019-12-02 21:04:41: Valid endpoint found: X.X.X.X:1194:udp
2019-12-02 21:04:41: WARNING: No server certificate verification method has been enabled.  See http://openvpn.net/howto.html#mitm for more info.
2019-12-02 21:04:41: PKCS#11: Creating a new session
2019-12-02 21:04:41: PKCS#11: Get certificate attributes failed: 179:'CKR_SESSION_HANDLE_INVALID'
2019-12-02 21:04:41: PKCS#11: Using cached session
2019-12-02 21:04:41: PKCS#11: Using cached session
2019-12-02 21:04:43: PKCS#11: Using cached session
2019-12-02 21:04:43: Outgoing Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
2019-12-02 21:04:43: Incoming Control Channel Authentication: Using 512 bit message hash 'SHA512' for HMAC authentication
2019-12-02 21:04:43: crypto_adjust_frame_parameters: Adjusting frame parameters for crypto by 72 bytes
2019-12-02 21:04:43: LZO compression initializing
2019-12-02 21:04:43: Control Channel MTU parms [ L:1622 D:1140 EF:110 EB:0 ET:0 EL:3 ]
2019-12-02 21:04:43: Data Channel MTU parms [ L:1622 D:1450 EF:122 EB:406 ET:0 EL:3 ]
2019-12-02 21:04:43: crypto_adjust_frame_parameters: Adjusting frame parameters for crypto by 100 bytes
2019-12-02 21:04:43: calc_options_string_link_mtu: link-mtu 1622 -> 1602
2019-12-02 21:04:43: crypto_adjust_frame_parameters: Adjusting frame parameters for crypto by 100 bytes
2019-12-02 21:04:43: calc_options_string_link_mtu: link-mtu 1622 -> 1602
2019-12-02 21:04:43: Local Options String (VER=V4): 'V4,dev-type tun,link-mtu 1602,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 1,cipher AES-256-CBC,auth SHA512,keysize 256,tls-auth,key-method 2,tls-client'
2019-12-02 21:04:43: Expected Remote Options String (VER=V4): 'V4,dev-type tun,link-mtu 1602,tun-mtu 1500,proto UDPv4,comp-lzo,keydir 0,cipher AES-256-CBC,auth SHA512,keysize 256,tls-auth,key-method 2,tls-server'
2019-12-02 21:04:43: TCP/UDP: Preserving recently used remote address: [AF_INET]X.X.X.X:1194
2019-12-02 21:04:43: Socket Buffers: R=[786896->786896] S=[9216->9216]
2019-12-02 21:04:43: UDP link local: (not bound)
2019-12-02 21:04:43: UDP link remote: [AF_INET]X.X.X.X:1194
2019-12-02 21:04:43: State changed to Authenticating
2019-12-02 21:04:43: TLS: Initial packet from [AF_INET]X.X.X.X:1194, sid=70e8f0e7 399fa5ad
2019-12-02 21:04:43: VERIFY OK: depth=2, C=US, O=Company, Inc., CN=Company Internal Root CA
2019-12-02 21:04:43: VERIFY OK: depth=1, C=US, O=Company, Inc., CN=Company Internal Intermediate CA
2019-12-02 21:04:43: VERIFY OK: depth=0, C=US, ST=California, L=San Francisco, O=Company, Inc., CN=vpn.company.com
2019-12-02 21:04:43: OpenSSL: error:141F0006:SSL routines:tls_construct_cert_verify:EVP lib
2019-12-02 21:04:43: TLS_ERROR: BIO read tls_read_plaintext error
2019-12-02 21:04:43: TLS Error: TLS object -> incoming plaintext read error
2019-12-02 21:04:43: TLS Error: TLS handshake failed
2019-12-02 21:04:43: TCP/UDP: Closing socket
2019-12-02 21:04:43: SIGTERM[soft,tls-error] received, process exiting
2019-12-02 21:04:43: PKCS#11: Terminating openssl
2019-12-02 21:04:43: PKCS#11: Removing providers
2019-12-02 21:04:43: PKCS#11: Removing provider '/Library/OpenSC/lib/opensc-pkcs11.so'
2019-12-02 21:04:43: State changed to Disconnected

James

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

Post by James » Sun Dec 08, 2019 11:52 pm
Hi salt_of_the_moon,

We've just released an updated beta version that addresses an issue with some PKCS#11 signatures. This may not be what us causing your issue, but I recommend giving it a try to see if it helps:
https://www.sparklabs.com/support/kb/article/using-viscosity-beta-versions/

If you're still stuck, it's possible your certificate ID is using an out-of-date format. Try editing your connection in Viscosity, clicking on the Authentication tab, change the PKCS11 Retrieval option to "Prompt for certificate name" (if it isn't already), and then click Save. Try connecting and see if you have any better luck.

You also mention you're using a Yubikey: Yubikeys are particular about what slot your identity is stored in. While it may have worked with an older version of OpenSC/OpenSSL, you may need to change the slot used to get it to work correctly with newer versions. I'm afraid you'll need to refer to YubiCo's documentation on the matter, however the last comment here may be of some help:
https://github.com/OpenSC/OpenSC/issues/1545

Finally, if your certificate is old-ish, OpenSSL may be requesting it if it is using out of date or insecure parameters. I would recommend trying to use the certificate directly with OpenVPN (i.e. not using PKCS#11) and see if it is accepted without issue to rule out any issues with the certificate itself.

Cheers,
James
Web: https://www.sparklabs.com
Support: https://www.sparklabs.com/support
Twitter: https://twitter.com/sparklabs

salt_of_the_moon

User avatar
Posts: 9
Joined: Sat May 27, 2017 8:09 am

Post by salt_of_the_moon » Fri Dec 13, 2019 6:26 am
Hi James,

I downloaded 1.8.4b2 (1523) and it appears to have fixed the issue!

Thanks for your work on this. Looking forward to this patch making it into the official release. :)

James

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

Post by James » Fri Dec 13, 2019 8:05 pm
Thanks for the feedback - great to hear it resolved the issue.

Cheers,
James
Web: https://www.sparklabs.com
Support: https://www.sparklabs.com/support
Twitter: https://twitter.com/sparklabs
9 posts Page 1 of 1