"Authentication Failed" error for long lived connections

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

acronce

Posts: 10
Joined: Mon Sep 18, 2017 5:01 am

Post by acronce » Sat Jun 02, 2018 4:39 am
Hi all,

We've been using OpenVPN and Viscosity successfully at our office for quite a while. We recently deployed a new OpenVPN 2.5.2 server at a remote location. This is an Access Server, not the Community Edition, in case that's relevant.

While things are largely working, we're seeing that connections that run for an extended period (like overnight) always eventually terminate with an "Authentication Failed" dialog. Once this happens, the failure seems to "stick". Attempts to reconnect fail until we cancel out and disable the connection. When the connection is reenabled, it works again. Until somewhere around 24 hours where the same problem happens again.

This problem isn't isolated to one person or location. Everyone who has a long lived overnight connection sees this failure. This includes people who are offsite as well as in the office, so with at least three different ISPs involved it seems unlikely to be Internet connectivity related. Most of us are using the latest shipping version of Viscosity.

After searching this forum it sounds like this issue might be resolved in a recent beta of Viscosity. But I tried Viscosity 1.7.10b2 (1452) and it doesn't resolve the problem.

One other fact that might be related is that we're running our 2.5.2 OpenVPN server in high availability mode. When we were testing this configuration, we killed one server and let the other one take over. When we did this, we saw the same kind of "Authentication Failed" behavior. Namely the failure was sticky until we disable and reenable the connection.

When we ran into this we figured failover was such a rare problem that it wasn't worth reporting. But now we're seeing what appears to be the same behavior on a daily basis without the server failing over, it seems like this is a bug that is worth understanding.

I'm not saying that something related to the high availability configuration is causing the problem. I'm suggesting that that is one reliable way of reproducing what seems to be the same client side failure. Perhaps it would be easier to debug than waiting 24-ish hours. Or at the very least, maybe there's some similarity between the cases that might help with an "ah-ha" moment that explains the problem.

In case the client side logs are helpful, I've included them here (scrubbing our IP addresses):
Code: Select all
2018-05-31 10:00:12: Viscosity Mac 1.7.10b2 (1452)
2018-05-31 10:00:12: Viscosity OpenVPN Engine Started
2018-05-31 10:00:12: Running on macOS 10.12.6
2018-05-31 10:00:12: ---------
2018-05-31 10:00:12: State changed to Connecting
2018-05-31 10:00:12: Checking reachability status of connection...
2018-05-31 10:00:12: Connection is reachable. Starting connection attempt.
2018-05-31 10:00:12: OpenVPN 2.4.6 x86_64-apple-darwin [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [MH/RECVDA] [AEAD] built on Apr 25 2018
2018-05-31 10:00:12: library versions: OpenSSL 1.0.2o  27 Mar 2018, LZO 2.10
2018-05-31 10:00:13: WARNING: --ns-cert-type is DEPRECATED.  Use --remote-cert-tls instead.
2018-05-31 10:00:13: TCP/UDP: Preserving recently used remote address: [AF_INET]1.2.3.4:1194
2018-05-31 10:00:13: UDP link local: (not bound)
2018-05-31 10:00:13: UDP link remote: [AF_INET]1.2.3.4:1194
2018-05-31 10:00:14: State changed to Authenticating
2018-05-31 10:00:14: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
2018-05-31 10:00:14: [OpenVPN Server] Peer Connection Initiated with [AF_INET]1.2.3.4:1194
2018-05-31 10:00:15: Unrecognized option or missing or extra parameter(s) in [PUSH-OPTIONS]:4: dhcp-pre-release (2.4.6)
2018-05-31 10:00:15: Unrecognized option or missing or extra parameter(s) in [PUSH-OPTIONS]:5: dhcp-renew (2.4.6)
2018-05-31 10:00:15: Unrecognized option or missing or extra parameter(s) in [PUSH-OPTIONS]:6: dhcp-release (2.4.6)
2018-05-31 10:00:15: Unrecognized option or missing or extra parameter(s) in [PUSH-OPTIONS]:25: register-dns (2.4.6)
2018-05-31 10:00:15: Unrecognized option or missing or extra parameter(s) in [PUSH-OPTIONS]:26: block-ipv6 (2.4.6)
2018-05-31 10:00:15: Opened utun device utun1
2018-05-31 10:00:15: do_ifconfig, tt->did_ifconfig_ipv6_setup=0
2018-05-31 10:00:15: /sbin/ifconfig utun1 delete
2018-05-31 10:00:15: NOTE: Tried to delete pre-existing tun/tap instance -- No Problem if failure
2018-05-31 10:00:15: /sbin/ifconfig utun1 172.28.232.114 172.28.232.114 netmask 255.255.248.0 mtu 1500 up
2018-05-31 10:00:20: Initialization Sequence Completed
2018-05-31 10:00:20: DNS mode set to Split
2018-05-31 10:00:20: WARNING: Split DNS is being used however no DNS domains are present. The DNS server/s for this connection may not be used. For more information please see: https://www.sparklabs.com/support/kb/article/warning-split-dns-is-being-used-however-no-dns-domains-are-present/
2018-05-31 10:00:20: State changed to Connected
2018-06-01 10:00:16: AUTH: Received control message: AUTH_FAILED,SESSION: Your session has expired, please reauthenticate
2018-06-01 10:00:16: SIGUSR1[soft,auth-failure] received, process restarting
2018-06-01 10:00:16: Viscosity Mac 1.7.10b2 (1452)
2018-06-01 10:00:16: Viscosity OpenVPN Engine Started
2018-06-01 10:00:16: Running on macOS 10.12.6
2018-06-01 10:00:16: ---------
2018-06-01 10:00:16: State changed to Connecting
2018-06-01 10:00:16: WARNING: --ns-cert-type is DEPRECATED.  Use --remote-cert-tls instead.
2018-06-01 10:00:16: TCP/UDP: Preserving recently used remote address: [AF_INET]1.2.3.4:1194
2018-06-01 10:00:16: UDP link local: (not bound)
2018-06-01 10:00:16: UDP link remote: [AF_INET]1.2.3.4:1194
2018-06-01 10:00:16: State changed to Authenticating
2018-06-01 10:00:16: WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1550', remote='link-mtu 1558'
2018-06-01 10:00:16: WARNING: 'cipher' is used inconsistently, local='cipher AES-256-GCM', remote='cipher AES-256-CBC'
2018-06-01 10:00:16: WARNING: 'auth' is used inconsistently, local='auth [null-digest]', remote='auth SHA1'
2018-06-01 10:00:16: [OpenVPN Server] Peer Connection Initiated with [AF_INET]1.2.3.4:1194
2018-06-01 10:00:17: AUTH: Received control message: AUTH_FAILED
2018-06-01 10:00:17: SIGUSR1[soft,auth-failure] received, process restarting
2018-06-01 11:02:40: Viscosity Mac 1.7.10b2 (1452)
2018-06-01 11:02:40: Viscosity OpenVPN Engine Started
2018-06-01 11:02:40: Running on macOS 10.12.6
2018-06-01 11:02:40: ---------
2018-06-01 11:02:40: State changed to Connecting
2018-06-01 11:02:42: State changed to Disconnecting
2018-06-01 11:02:42: ERROR: could not read Auth username/password/ok/string from management interface
2018-06-01 11:02:42: Fri Jun  1 11:02:42 2018 Exiting due to fatal error
2018-06-01 11:02:42: State changed to Disconnected
2018-06-01 11:02:43: Viscosity Mac 1.7.10b2 (1452)
2018-06-01 11:02:43: Viscosity OpenVPN Engine Started
2018-06-01 11:02:43: Running on macOS 10.12.6
2018-06-01 11:02:43: ---------
2018-06-01 11:02:43: State changed to Connecting
2018-06-01 11:02:44: Checking reachability status of connection...
2018-06-01 11:02:44: Connection is reachable. Starting connection attempt.
2018-06-01 11:02:44: OpenVPN 2.4.6 x86_64-apple-darwin [SSL (OpenSSL)] [LZO] [LZ4] [PKCS11] [MH/RECVDA] [AEAD] built on Apr 25 2018
2018-06-01 11:02:44: library versions: OpenSSL 1.0.2o  27 Mar 2018, LZO 2.10
2018-06-01 11:02:45: WARNING: --ns-cert-type is DEPRECATED.  Use --remote-cert-tls instead.
2018-06-01 11:02:45: TCP/UDP: Preserving recently used remote address: [AF_INET]1.2.3.4:1194
2018-06-01 11:02:45: UDP link local: (not bound)
2018-06-01 11:02:45: UDP link remote: [AF_INET]1.2.3.4:1194
2018-06-01 11:02:45: State changed to Authenticating
2018-06-01 11:02:45: WARNING: this configuration may cache passwords in memory -- use the auth-nocache option to prevent this
2018-06-01 11:02:45: [OpenVPN Server] Peer Connection Initiated with [AF_INET]1.2.3.4:1194
2018-06-01 11:02:46: Unrecognized option or missing or extra parameter(s) in [PUSH-OPTIONS]:4: dhcp-pre-release (2.4.6)
2018-06-01 11:02:46: Unrecognized option or missing or extra parameter(s) in [PUSH-OPTIONS]:5: dhcp-renew (2.4.6)
2018-06-01 11:02:46: Unrecognized option or missing or extra parameter(s) in [PUSH-OPTIONS]:6: dhcp-release (2.4.6)
2018-06-01 11:02:46: Unrecognized option or missing or extra parameter(s) in [PUSH-OPTIONS]:25: register-dns (2.4.6)
2018-06-01 11:02:46: Unrecognized option or missing or extra parameter(s) in [PUSH-OPTIONS]:26: block-ipv6 (2.4.6)
2018-06-01 11:02:46: Opened utun device utun1
2018-06-01 11:02:46: do_ifconfig, tt->did_ifconfig_ipv6_setup=0
2018-06-01 11:02:46: /sbin/ifconfig utun1 delete
2018-06-01 11:02:46: NOTE: Tried to delete pre-existing tun/tap instance -- No Problem if failure
2018-06-01 11:02:46: /sbin/ifconfig utun1 172.28.232.129 172.28.232.129 netmask 255.255.248.0 mtu 1500 up
2018-06-01 11:02:52: Initialization Sequence Completed
2018-06-01 11:02:52: DNS mode set to Split
2018-06-01 11:02:52: WARNING: Split DNS is being used however no DNS domains are present. The DNS server/s for this connection may not be used. For more information please see: https://www.sparklabs.com/support/kb/article/warning-split-dns-is-being-used-however-no-dns-domains-are-present/
2018-06-01 11:02:52: State changed to Connected
Thanks in advance for any help resolving this issue.

James

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

Post by James » Wed Jun 06, 2018 8:05 pm
Hi acronce,

What you're running into is related to session tokens. OpenVPN-AS automatically generates a session token when a user successfully connects: this allows a user to avoid needing to re-enter their credentials (or re-authenticate using two-factor) for short disconnects, dropouts, sleeps, etc

After being connected for a long time (I believe OpenVPN AS's default is 24 hours) the session token will eventually expire (for security reasons) and so if a dropout occurs, or a regular TLS session re-key, the cached session token will be rejected by the server. The client should then attempt to re-authenticate as normal.

Viscosity has always handled session tokens correctly, and so normally this wouldn't be an issue. However unfortunately direct client session token support was recently added to OpenVPN itself, which doesn't work correctly. When the expired session token is rejected, instead of trying again with the proper credentials, it'll just keep trying the session token forever. I believe a fix is coming in the next OpenVPN update, however in the meantime you have a couple of options:

1. Have Viscosity handle the session token, which will handle it correctly. The trick to this is to let Viscosity handle reconnects rather than OpenVPN. To do this, make sure the "Automatically reconnect if disconnected" option is ticked under the General tab when editing the connection, and then add the command "remap-usr1 SIGTERM" (without quotes) to the advanced commands area:
https://www.sparklabs.com/support/kb/ar ... -commands/

2. Either disable session tokens inside OpenVPN-AS, or extend the session token expiration period. I believe the documentation here should help:
https://docs.openvpn.net/command-line/o ... t-options/

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

acronce

Posts: 10
Joined: Mon Sep 18, 2017 5:01 am

Post by acronce » Thu Jun 07, 2018 4:31 am
Thanks for getting back to me James.

I'll try option #1 and leave it running overnight to test it.

acronce

Posts: 10
Joined: Mon Sep 18, 2017 5:01 am

Post by acronce » Fri Jun 08, 2018 7:18 am
Unfortunately I got the same authentication error. This is after making the recommended config changes under suggestion #1, connecting, then waiting.

So I guess I should try recommendation #2? It seems less desirable to make server side changes.

Also, I just got a notification of 1.7.10b3 (under the authentication error, so it happened around the same time). Should I go ahead and update to that version?

James

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

Post by James » Fri Jun 15, 2018 7:44 pm
Hi acronce,

We've gone ahead and patched OpenVPN to disable its inbuilt session token support in the latest beta version of Viscosity. This should resolve the issue you're having with expired session tokens, as Viscosity itself will handle them. Please give it a try and let us know if you run into any issues.
https://www.sparklabs.com/support/kb/ar ... -versions/

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

acronce

Posts: 10
Joined: Mon Sep 18, 2017 5:01 am

Post by acronce » Wed Jun 27, 2018 5:33 am
Thanks for the follow up James. I didn't see your reply right away. I guess I don't have forum notifications enabled.

In any case, I updated to your latest beta yesterday and have successfully kept an open connection for over 24 hours. Looks like your fix works.

Thanks again for your help.
6 posts Page 1 of 1