OpenVPN Access Server 2.7.x session token issues

chaz_ex

Hello.

I've experienced the issues with the session tokens after updated OpenVPN AS from 2.6.1 to the latest version 2.7.4. According to the https://openvpn.net/vpn-server-resources/openvpn-tunnel-session-management-options/ there are some conditions which describes when the session token should expire, but at least two of them are not working anymore:

The session token is locked to the client IP address of the successful authentication (cannot be used from another IP).
Session tokens expire automatically when left unused for a while, 5 minutes by default.

I downgraded the version to 2.7.3, but the issues still there. However the version 2.6.1 works as expected. Is this a server bug in the new versions?

Here are the details:

Environment:

Operating system: CentOS Linux release 7.6.1810 (Core)
OpenVPN AS package version: openvpn-as-2.7.4_777bcfe6-CentOSrelease.x86_64
OpenVPN client: Viscosity 1.7.16 (1491)

Default configuration:

vpn.server.session_ip_lock -> true
vpn.server.inactive_expire -> 300 seconds
local user authentication

My steps to reproduce:

Connect OpenVPN tunnel
Drop the vpn connection (not gracefully disconnect)
Wait for 10 minutes and then connect it again by using different ip address (by other ISP)

Expected behaviour:
The server should ask for credentials again and the user must reauthenticate. Such behavior is in the version 2.6.1

Actual behaviour:
OpenVPN client successfully connected without asking credentials. The server log says:

2019-07-23T12:13:15+0000 [stdout#info] AUTH SUCCESS {'status': 0, 'session_id': '[redacted]', 'reason': 'SESSION_ID HMAC session continuation succeeded', 'serial_list': [], 'user': u'testuser', 'proplist': {u'pvt_password_digest': '[redacted]', u'type': u'user_connect', u'prop_autogenerate': u'true'}, 'common_name': u'testuser', 'serial': '2', 'create_new_session': True} cli=u'mac'/u'2.4.7'

The server log:

2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 TLS: Initial packet from [AF_INET]x.x.x.x:64735 (via [AF_INET]z.z.z.z%eth0), sid=115dcd7f d512f2c2'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 VERIFY OK: depth=1, /CN=OpenVPN CA'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 VERIFY OK: nsCertType=CLIENT'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 VERIFY OK: depth=0, /CN=testuser'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 peer info: IV_VER=2.4.7'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 peer info: IV_PLAT=mac'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 peer info: IV_PROTO=2'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 peer info: IV_NCP=2'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 peer info: IV_LZ4=1'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 peer info: IV_LZ4v2=1'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 peer info: IV_LZO=1'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 peer info: IV_COMP_STUB=1'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 peer info: IV_COMP_STUBv2=1'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 peer info: IV_TCPNL=1'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 peer info: IV_SSL=OpenSSL_1.0.2s__28_May_2019'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 peer info: IV_GUI_VER=Viscosity_1.7.16_1491'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: "Tue Jul 23 12:02:00 2019 x.x.x.x:64735 TLS: Username/Password authentication deferred for username 'testuser' "
2019-07-23T12:02:00+0000 [stdout#info] ::.[usersvc.py, Line 571] Client created.::
2019-07-23T12:02:00+0000 [stdout#info] **** CLIENT_CONNECT User=u'testuser', CN=u'testuser', DID/CID=('10', 0), SerList=()
2019-07-23T12:02:00+0000 [stdout#info] FORCE_UNIQUE False
2019-07-23T12:02:00+0000 [stdout#info] CC_CMDS
2019-07-23T12:02:00+0000 [stdout#info] compress stub-v2
2019-07-23T12:02:00+0000 [stdout#info] push "compress stub-v2"
2019-07-23T12:02:00+0000 [stdout#info] push "redirect-gateway def1"
2019-07-23T12:02:00+0000 [stdout#info] push "redirect-gateway bypass-dhcp"
2019-07-23T12:02:00+0000 [stdout#info] push "redirect-gateway autolocal"
2019-07-23T12:02:00+0000 [stdout#info] ifconfig-push 172.27.234.2 255.255.255.0
2019-07-23T12:02:00+0000 [stdout#info] push "route-gateway 172.27.234.1"
2019-07-23T12:02:00+0000 [stdout#info] push "register-dns"
2019-07-23T12:02:00+0000 [stdout#info] push "block-ipv6"
2019-07-23T12:02:00+0000 [stdout#info] ACTIONS
2019-07-23T12:02:00+0000 [stdout#info] <ActionEffect func=<function <lambda> at 0x7fa59fc53e60> type='mod_inc'>
2019-07-23T12:02:00+0000 [stdout#info] <ActionEffect func=<function <lambda> at 0x7fa59fc20ed8> type='sess_incr_refcount'>
2019-07-23T12:02:00+0000 [stdout#info] UNDO_ACTIONS
2019-07-23T12:02:00+0000 [stdout#info] <ActionEffect func=<function <lambda> at 0x7fa59f99ca28> type='dynamic_ip'>
2019-07-23T12:02:00+0000 [stdout#info] <ActionEffect func=<function <lambda> at 0x7fa59fc53cf8> type='mod_dec'>
2019-07-23T12:02:00+0000 [stdout#info] <ActionEffect func=<function <lambda> at 0x7fa59f99c848> type='sess_decr_refcount'>
2019-07-23T12:02:00+0000 [stdout#info] ****
2019-07-23T12:02:00+0000 [stdout#info] AUTH SUCCESS {'status': 0, 'reason': 'local auth succeeded', 'serial_list': [], 'user': u'testuser', 'proplist': {u'pvt_password_digest': '[redacted]', u'type': u'user_connect', u'prop_autogenerate': u'true'}, 'common_name': u'testuser', 'serial': '2'} cli=u'mac'/u'2.4.7'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: "Tue Jul 23 12:02:00 2019 MANAGEMENT: CMD 'client-auth 0 0'"
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 x.x.x.x:64735 [testuser] Peer Connection Initiated with [AF_INET]x.x.x.x:64735 (via [AF_INET]z.z.z.z%eth0)'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 testuser/x.x.x.x:64735 OPTIONS IMPORT: compression parms modified'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 testuser/x.x.x.x:64735 MULTI: Learn: 172.27.234.2 -> testuser/x.x.x.x:64735'
2019-07-23T12:02:00+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:02:00 2019 testuser/x.x.x.x:64735 MULTI: primary virtual IP for testuser/x.x.x.x:64735: 172.27.234.2'
2019-07-23T12:02:01+0000 [stdout#info] [OVPN 10] OUT: "Tue Jul 23 12:02:01 2019 testuser/x.x.x.x:64735 PUSH: Received control message: 'PUSH_REQUEST'"
2019-07-23T12:02:01+0000 [stdout#info] [OVPN 10] OUT: "Tue Jul 23 12:02:01 2019 testuser/x.x.x.x:64735 SENT CONTROL [testuser]: 'PUSH_REPLY,explicit-exit-notify,topology subnet,route-delay 5 30,dhcp-pre-release,dhcp-renew,dhcp-release,route-metric 101,ping 12,ping-restart 50,compress stub-v2,redirect-gateway def1,redirect-gateway bypass-dhcp,redirect-gateway autolocal,route-gateway 172.27.234.1,dhcp-option DNS z.z.z.z,register-dns,block-ipv6,ifconfig 172.27.234.2 255.255.255.0,peer-id 0,auth-tokenSESS_ID,cipher AES-256-GCM' (status=1)"
2019-07-23T12:02:01+0000 [stdout#info] [OVPN 10] OUT: "Tue Jul 23 12:02:01 2019 testuser/x.x.x.x:64735 Data Channel: using negotiated cipher 'AES-256-GCM'"
2019-07-23T12:02:01+0000 [stdout#info] [OVPN 10] OUT: "Tue Jul 23 12:02:01 2019 testuser/x.x.x.x:64735 Outgoing Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key"
2019-07-23T12:02:01+0000 [stdout#info] [OVPN 10] OUT: "Tue Jul 23 12:02:01 2019 testuser/x.x.x.x:64735 Incoming Data Channel: Cipher 'AES-256-GCM' initialized with 256 bit key"
2019-07-23T12:04:40+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:04:40 2019 testuser/x.x.x.x:64735 [testuser] Inactivity timeout (--ping-restart), restarting'
2019-07-23T12:04:40+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:04:40 2019 testuser/x.x.x.x:64735 SIGUSR1[soft,ping-restart] received, client-instance restarting'
2019-07-23T12:13:08+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:08 2019 y.y.y.y:64850 TLS: Initial packet from [AF_INET]y.y.y.y:64850 (via [AF_INET]z.z.z.z%eth0), sid=c2fcf703 9eb18795'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 VERIFY OK: depth=1, /CN=OpenVPN CA'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 VERIFY OK: nsCertType=CLIENT'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 VERIFY OK: depth=0, /CN=testuser'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 peer info: IV_VER=2.4.7'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 peer info: IV_PLAT=mac'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 peer info: IV_PROTO=2'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 peer info: IV_NCP=2'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 peer info: IV_LZ4=1'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 peer info: IV_LZ4v2=1'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 peer info: IV_LZO=1'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 peer info: IV_COMP_STUB=1'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 peer info: IV_COMP_STUBv2=1'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 peer info: IV_TCPNL=1'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 peer info: IV_SSL=OpenSSL_1.0.2s__28_May_2019'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 peer info: IV_GUI_VER=Viscosity_1.7.16_1491'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: "Tue Jul 23 12:13:15 2019 y.y.y.y:64850 TLS: Username/Password authentication deferred for username 'testuser' "
2019-07-23T12:13:15+0000 [stdout#info] ::.[usersvc.py, Line 571] Client created.::
2019-07-23T12:13:15+0000 [stdout#info] **** CLIENT_CONNECT User=u'testuser', CN=u'testuser', DID/CID=('10', 1), SerList=()
2019-07-23T12:13:15+0000 [stdout#info] FORCE_UNIQUE False
2019-07-23T12:13:15+0000 [stdout#info] CC_CMDS
2019-07-23T12:13:15+0000 [stdout#info] compress stub-v2
2019-07-23T12:13:15+0000 [stdout#info] push "compress stub-v2"
2019-07-23T12:13:15+0000 [stdout#info] push "redirect-gateway def1"
2019-07-23T12:13:15+0000 [stdout#info] push "redirect-gateway bypass-dhcp"
2019-07-23T12:13:15+0000 [stdout#info] push "redirect-gateway autolocal"
2019-07-23T12:13:15+0000 [stdout#info] ifconfig-push 172.27.234.3 255.255.255.0
2019-07-23T12:13:15+0000 [stdout#info] push "route-gateway 172.27.234.1"
2019-07-23T12:13:15+0000 [stdout#info] push "register-dns"
2019-07-23T12:13:15+0000 [stdout#info] push "block-ipv6"
2019-07-23T12:13:15+0000 [stdout#info] ACTIONS
2019-07-23T12:13:15+0000 [stdout#info] <ActionEffect func=<function <lambda> at 0x7fa59fc53398> type='mod_inc'>
2019-07-23T12:13:15+0000 [stdout#info] UNDO_ACTIONS
2019-07-23T12:13:15+0000 [stdout#info] <ActionEffect func=<function <lambda> at 0x7fa59fc20320> type='dynamic_ip'>
2019-07-23T12:13:15+0000 [stdout#info] <ActionEffect func=<function <lambda> at 0x7fa59fc53b90> type='mod_dec'>
2019-07-23T12:13:15+0000 [stdout#info] ****
2019-07-23T12:13:15+0000 [stdout#info] AUTH SUCCESS {'status': 0, 'session_id': '[redacted]', 'reason': 'SESSION_ID HMAC session continuation succeeded', 'serial_list': [], 'user': u'testuser', 'proplist': {u'pvt_password_digest': '[redacted]', u'type': u'user_connect', u'prop_autogenerate': u'true'}, 'common_name': u'testuser', 'serial': '2', 'create_new_session': True} cli=u'mac'/u'2.4.7'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: "Tue Jul 23 12:13:15 2019 MANAGEMENT: CMD 'client-auth 1 0'"
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 Control Channel: TLSv1.2, cipher TLSv1/SSLv3 ECDHE-RSA-AES256-GCM-SHA384, 2048 bit RSA'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 y.y.y.y:64850 [testuser] Peer Connection Initiated with [AF_INET]y.y.y.y:64850 (via [AF_INET]z.z.z.z%eth0)'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 testuser/y.y.y.y:64850 OPTIONS IMPORT: compression parms modified'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 testuser/y.y.y.y:64850 MULTI: Learn: 172.27.234.3 -> testuser/y.y.y.y:64850'
2019-07-23T12:13:15+0000 [stdout#info] [OVPN 10] OUT: 'Tue Jul 23 12:13:15 2019 testuser/y.y.y.y:64850 MULTI: primary virtual IP for testuser/y.y.y.y:64850: 172.27.234.3'

The Johan

I think this is a regression that's being (mostly) addressed in the upcoming 2.7.5 release. It is at least something known here and caused by adding new functionality for clustering. Sorry for the inconvenience.

chaz_ex

Thank you for your feedback. Is there any chance that it will be solved in the upcoming release?

The Johan

As I said, it is being addressed in the upcoming 2.7.5 release.

sophiapage

I am facing this type of error on my device. It is happening after connection my Epson printer to my device. If you have any idea about Epson Printer Error 0xf1, please help me.

maniqui

Issue is still present on release 2.7.5. Connection persists (ie. client gets reconnected) after switching to a different public IP address.

The Johan

The issue is marked as resolved here - it adheres to the 24 hour session timeout just fine. But you seem to be talking about another issue, about session IP locking. Are you using clustering feature?

maniqui

@novaflash, this thread is about session IP locking not working on v2.7.x. OP originally reported it happening on v2.7.4 and v2.7.3. I just confirmed it's still happening on v.2.7.5: switching to a different Internet connection (ie. a different public IP address) reauthenticates the user without prompting for credentials again.
On this thread, there's no mention of the 24 hour session timeout issue, although I've seen that one is confirmed as fixed on release v2.7.5.

The Johan

Right. Probably that is affected by clustering functionality.

chaz_ex

I would like to add that besides the session IP locking issue, there is also an issue with the session token inactivity timeout (vpn.server.inactive_expire setting, default 5 minutes) which isn't working on v2.7.5. As a result, there is a potential security risk by using the latest openvpn AS 2.7.5 release.