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.
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)
- vpn.server.session_ip_lock -> true
- vpn.server.inactive_expire -> 300 seconds
- local user authentication
- 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)
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'
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'