Hi All,
I assume the issue from 2017 with auth-nocache + auth-token still exists.
However, I've bumped into something, which I cannot understand. Same setup
with OTP, but removed the 'auth-nocache' from the client.conf.
In server.conf the following is set:
reneg-sec 18000
auth-gen-token 39600
In the client.conf:
reneg-sec 18000
(auth-nocache is NOT set)
This is a TAP setup with external DHCP server (needed for client proxy
setting push). Management-client-auth is used with 'client-auth-nt' on
server side (works ok, but I don't see any 'REAUTH' message in logs - I
assuem this is due to the token auth)
I've connected to the server at 10:30:
Thu Apr 30 10:30:43 2020 us=121829 MANAGEMENT:
>STATE:1588235443,CONNECTED,SUCCESS,,SERVER_IP,443,192.168.0.52,54937
Next messages in client log (these should be the DHCP periodic messages,
dhcp-lease-time 14400; max-lease-time 43200):
Thu Apr 30 12:30:39 2020 us=429095 Extracted DHCP router address: 10.14.12.1
Thu Apr 30 14:30:39 2020 us=62016 Extracted DHCP router address: 10.14.12.1
At 15:30 the key expired (18000s = 5 hours), data-connetion reinitiated
('TLS: soft reset' + 'TLS: Username/auth-token authentication succeeded for
username' in server.log ) :
Thu Apr 30 15:30:33 2020 us=405908 Outgoing Data Channel: Cipher
'AES-256-GCM' initialized with 256 bit key
Thu Apr 30 15:30:33 2020 us=405908 Incoming Data Channel: Cipher
'AES-256-GCM' initialized with 256 bit key
Thu Apr 30 15:30:33 2020 us=406908 Control Channel: TLSv1.2, cipher TLSv1.2
ECDHE-ECDSA-AES256-GCM-SHA384, 521 bit EC, curve: secp521r1
However, at 16:30 I got disconnected, which I did not understand (same
message in client.log and server.log):
Thu Apr 30 16:30:31 2020 us=11284 TLS: tls_process: killed expiring key
Thu Apr 30 16:30:31 2020 us=876533 Connection reset, restarting [0]
What can be the issue? Why did I get disconnected at 16:30? auth-token
should be still valid, key-renegotioation should not happen, since just 1
hour passed since the last negotiation.
Cheers,
Tom
From: Dajka Tamás [mailto:vi...@vipernet.hu]
Sent: Monday, April 27, 2020 3:22 PM
To: openvpn-users@lists.sourceforge.net
Subject: [Openvpn-users] OTP + auth-token
Hi,
I'm still having trouble with OTP. Everything is set up, client is able to
connect (management-client-auth is used with client-auth-nt), but after 2
hours the client re-requests the credentials to log in (auth-nocache is set
on client, external DHCP is used with server-bridge). Server is
2.4.7@Debian10 <mailto:2.4.7@Debian10> , client is Win10(v11.14)
In the client log I have the following:
Mon Apr 27 11:30:13 2020 us=473611 MANAGEMENT:
>STATE:1587979813,GET_CONFIG,,,,,,
Mon Apr 27 11:30:13 2020 us=473611 SENT CONTROL [myvpn.domain.com]:
'PUSH_REQUEST' (status=1)
Mon Apr 27 11:30:18 2020 us=519013 SENT CONTROL [myvpn.domain.com]:
'PUSH_REQUEST' (status=1)
Mon Apr 27 11:30:18 2020 us=536968 PUSH: Received control message:
'PUSH_REPLY,redirect-gateway def1,router-gateway 10.14.12.1,route 10.14.0.0
255.255.0.0 10.14.12.1,ping 60,route-gateway dhcp,ping 10,ping-restart
120,socket-flags TCP_NODELAY,peer-id 0,cipher AES-256-GCM,auth-token'
Mon Apr 27 11:30:18 2020 us=536968 Options error: Unrecognized option or
missing or extra parameter(s) in [PUSH-OPTIONS]:2: router-gateway (2.4.8)
Mon Apr 27 11:30:18 2020 us=537963 OPTIONS IMPORT: timers and/or timeouts
modified
...
Mon Apr 27 11:30:23 2020 us=185637 MANAGEMENT:
>STATE:1587979823,CONNECTED,SUCCESS,,MYSERVER_IP,443,192.168.0.52,52182
Mon Apr 27 12:30:12 2020 us=117820 TLS: soft reset sec=0 bytes=97397169/-1
pkts=198208/0
Mon Apr 27 12:30:12 2020 us=145390 VERIFY OK: depth=1, CN=MyServer CA
Mon Apr 27 12:30:12 2020 us=148416 VERIFY KU OK
Mon Apr 27 12:30:12 2020 us=148416 Validating certificate extended key usage
Mon Apr 27 12:30:12 2020 us=148416 ++ Certificate has EKU (str) TLS Web
Server Authentication, expects TLS Web Server Authentication
Mon Apr 27 12:30:12 2020 us=148416 VERIFY EKU OK
Mon Apr 27 12:30:12 2020 us=148416 VERIFY X509NAME OK:
CN=myserver.domain.com
Mon Apr 27 12:30:12 2020 us=148416 VERIFY OK: depth=0,
CN=myserver.domain.com
Mon Apr 27 12:30:12 2020 us=177444 Outgoing Data Channel: Cipher
'AES-256-GCM' initialized with 256 bit key
Mon Apr 27 12:30:12 2020 us=177444 Incoming Data Channel: Cipher
'AES-256-GCM' initialized with 256 bit key
Mon Apr 27 12:30:12 2020 us=177444 Control Channel: TLSv1.2, cipher TLSv1.2
ECDHE-ECDSA-AES256-GCM-SHA384, 521 bit EC, curve: secp521r1
Mon Apr 27 13:30:12 2020 us=20692 TLS: soft reset sec=0 bytes=131243846/-1
pkts=301943/0
Mon Apr 27 13:30:12 2020 us=125662 Connection reset, restarting [0]
Mon Apr 27 13:30:12 2020 us=125662 TCP/UDP: Closing socket
Mon Apr 27 13:30:12 2020 us=126639 SIGUSR1[soft,connection-reset] received,
process restarting
Mon Apr 27 13:30:12 2020 us=126639 MANAGEMENT:
>STATE:1587987012,RECONNECTING,connection-reset,,,,,
Server log (verb 3 for now):
Mon Apr 27 11:30:10 2020 TCP connection established with
[AF_INET]CLIENT_PUB_IP:52182
Mon Apr 27 11:30:10 2020 Socket flags: TCP_NODELAY=1 succeeded
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 TLS: Initial packet from
[AF_INET]CLIENT_PUB_IP:52182, sid=9a1a5456 eb60e5a2
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 peer info: IV_VER=2.4.8
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 peer info: IV_PLAT=win
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 peer info: IV_PROTO=2
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 peer info: IV_NCP=2
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 peer info: IV_LZ4=1
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 peer info: IV_LZ4v2=1
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 peer info: IV_LZO=1
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 peer info: IV_COMP_STUB=1
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 peer info: IV_COMP_STUBv2=1
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 peer info: IV_TCPNL=1
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 peer info:
IV_GUI_VER=OpenVPN_GUI_11
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 TLS: Username/Password
authentication deferred for username 'MYUSER' [CN SET]
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 Control Channel: TLSv1.2,
cipher TLSv1.2 ECDHE-ECDSA-AES256-GCM-SHA384
Mon Apr 27 11:30:11 2020 CLIENT_PUB_IP:52182 [MYUSER] Peer Connection
Initiated with [AF_INET]CLIENT_PUB_IP:52182
Mon Apr 27 11:30:12 2020 CLIENT_PUB_IP:52182 PUSH: Received control message:
'PUSH_REQUEST'
Mon Apr 27 11:30:13 2020 MANAGEMENT: CMD 'client-auth-nt 137 0'
Mon Apr 27 11:30:13 2020 MYUSER/CLIENT_PUB_IP:52182 MULTI: no dynamic or
static remote --ifconfig address is available for MYUSER/CLIENT_PUB_IP:52182
Mon Apr 27 11:30:17 2020 MYUSER/CLIENT_PUB_IP:52182 PUSH: Received control
message: 'PUSH_REQUEST'
Mon Apr 27 11:30:17 2020 MYUSER/CLIENT_PUB_IP:52182 SENT CONTROL [MYUSER]:
'PUSH_REPLY,redirect-gateway def1,router-gateway 10.14.12.1,route 10.14.0.0
255.255.0.0 10.14.12.1,ping 60,route-gateway dhcp,ping 10,ping-restart
120,socket-flags TCP_NODELAY,peer-id 0,cipher AES-256-GCM,auth-token'
(status=1)
Mon Apr 27 11:30:17 2020 MYUSER/CLIENT_PUB_IP:52182 Outgoing Data Channel:
Cipher 'AES-256-GCM' initialized with 256 bit key
Mon Apr 27 11:30:17 2020 MYUSER/CLIENT_PUB_IP:52182 Incoming Data Channel:
Cipher 'AES-256-GCM' initialized with 256 bit key
Mon Apr 27 11:30:17 2020 MYUSER/CLIENT_PUB_IP:52182 MULTI: Learn:
00:ff:3b:1c:a6:93 -> MYUSER/CLIENT_PUB_IP:52182
...
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 TLS: soft reset sec=0
bytes=97417225/-1 pkts=198208/0
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 peer info: IV_VER=2.4.8
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 peer info: IV_PLAT=win
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 peer info: IV_PROTO=2
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 peer info: IV_LZ4=1
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 peer info: IV_LZ4v2=1
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 peer info: IV_LZO=1
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 peer info:
IV_COMP_STUB=1
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 peer info:
IV_COMP_STUBv2=1
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 peer info: IV_TCPNL=1
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 peer info:
IV_GUI_VER=OpenVPN_GUI_11
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 TLS: Username/auth-token
authentication succeeded for username 'MYUSER' [CN SET]
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 Outgoing Data Channel:
Cipher 'AES-256-GCM' initialized with 256 bit key
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 Incoming Data Channel:
Cipher 'AES-256-GCM' initialized with 256 bit key
Mon Apr 27 12:30:11 2020 MYUSER/CLIENT_PUB_IP:52182 Control Channel:
TLSv1.2, cipher TLSv1.2 ECDHE-ECDSA-AES256-GCM-SHA384
..
Mon Apr 27 13:30:10 2020 MYUSER/CLIENT_PUB_IP:52182
SIGTERM[soft,auth-control-exit] received, client-instance exiting
Mon Apr 27 13:30:14 2020 TCP connection established with
[AF_INET]CLIENT_PUB_IP:51401
Mon Apr 27 13:30:14 2020 Socket flags: TCP_NODELAY=1 succeeded
Mon Apr 27 13:30:15 2020 CLIENT_PUB_IP:51401 TLS: Initial packet from
[AF_INET]CLIENT_PUB_IP:51401, sid=560f6ec6 299adf12
Server config (relevant settings):
# we will use token after first successful auth
auth-gen-token 39600
keepalive 10 120
management /etc/openvpn/server/.server-auth-socket unix
management-client-auth
In the mgmt-client-auth log there is nothing for 12:30 timestamp (will log
REAUTH as well). reneg time is not set anywhere.
Why does the token expire after ~1-2 hours? I shouldn't use auth-token with
management-client-auth?
Thanks,
Tom
_______________________________________________
Openvpn-users mailing list
Openvpn-users@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/openvpn-users
