OpenVPN Access Server 2.7.x session token issues

Post Reply
chaz_ex
OpenVpn Newbie
Posts: 2
Joined: Tue May 07, 2019 4:13 pm

OpenVPN Access Server 2.7.x session token issues

Post by chaz_ex » Tue Jul 23, 2019 4:36 pm

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-resource ... t-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:
  1. Connect OpenVPN tunnel
  2. Drop the vpn connection (not gracefully disconnect)
  3. 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:

Code: Select all

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:

Code: Select all

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'

novaflash
I should be on the dev team.
Posts: 949
Joined: Fri Apr 13, 2012 8:43 pm

Re: OpenVPN Access Server 2.7.x session token issues

Post by novaflash » Tue Jul 23, 2019 9:54 pm

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
OpenVpn Newbie
Posts: 2
Joined: Tue May 07, 2019 4:13 pm

Re: OpenVPN Access Server 2.7.x session token issues

Post by chaz_ex » Wed Jul 24, 2019 7:28 am

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

novaflash
I should be on the dev team.
Posts: 949
Joined: Fri Apr 13, 2012 8:43 pm

Re: OpenVPN Access Server 2.7.x session token issues

Post by novaflash » Wed Jul 24, 2019 8:56 am

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

Post Reply