Authentication cache sometimes not working

ohad258 · February 13, 2024, 12:44pm

Hi,

Users in my company are getting disconnected from the VPN quite often.

By inspecting the logs I noticed that only those users sometime do not have the log line: “Storing authentication cache token” after the authenticate, which requires them to authenticate again.

Again, to clarify:

The expectation:

[summer-dreams-3351][2024-02-13 08:51:15,304][INFO] Authenticating user
  user_name = "user@company.com"
  factors   = ["google", "otp", "pin"]
[summer-dreams-3351][2024-02-13 08:51:17,343][INFO] Storing authentication cache token
  user_name = "user@company.com"
  factors   = ["google", "otp", "pin"]

what actually happens:

[summer-dreams-3351][2024-02-13 08:51:15,304][INFO] Authenticating user
  user_name = "user@company.com"
  factors   = ["google", "otp", "pin"]

“Pritunl Authentication Cache” is checked in the Settings (and most of users do not experience such issue).

Thanks.

zach · February 14, 2024, 9:45pm

They may need to reimport the profile, some older profiles don’t have the added encryption keys that allow for additional encryption. The profile may also need to be reimported if configuration sync isn’t working and the profile has the Pritunl client cache was enabled on the server after the profile was imported. It could be an older Pritunl client with the older cache design that is no longer supported. Only the Pritunl Client will work with the cache, other OpenVPN clients don’t have the functionality.

ohad258 · March 5, 2024, 9:28am

None of you suggestions worked. We can see that when it happens to some users the error ‘"ERROR User auth failed “Duplicate nonce”’ is logged to the Server Output.

If we reset the VPN server, it fixes the problem for one user, but creates the same problem to another user (problem of getting disconnected every few hours or less).

ohad258 · March 5, 2024, 9:40am

Those were the last logs of user which got disconnected, in 10:50 (anonymized few strings) - VPN logs:

2024-03-05 10:50:58 1 variation(s) on previous 3 message(s) suppressed by --mute
2024-03-05 10:50:58 Connection reset command was pushed by server ('')
2024-03-05 10:50:58 SIGUSR1[soft,server-pushed-connection-reset] received, process restarting
2024-03-05 10:51:00 NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
2024-03-05 10:51:00 TCP/UDP: Preserving recently used remote address: [AF_INET]X.XXX.XX.XX:XXXXX
2024-03-05 10:51:00 UDPv4 link local: (not bound)
2024-03-05 10:51:00 UDPv4 link remote: [AF_INET]X.XXX.XX.XX:XXXXX
2024-03-05 10:51:00 VERIFY SCRIPT OK: depth=1, O=6453591c269dxxxxxxxxxxxx, CN=6453591c269dxxxxxxxxxxxx
2024-03-05 10:51:00 NOTE: --mute triggered...
2024-03-05 10:51:00 8 variation(s) on previous 3 message(s) suppressed by --mute
2024-03-05 10:51:00 [6453591d269d8xxxxxxxxxxxx] Peer Connection Initiated with [AF_INET]X.XXX.XX.XX:XXXXX
2024-03-05 10:51:01 AUTH: Received control message: AUTH_FAILED
2024-03-05 10:51:01 /tmp/pritunl/8d47797dxxxxxxxxxxxx-down.sh utun5 1500 0 192.168.217.7 255.255.255.0 init
delete net 10.192.0.0: gateway 192.168.217.1
delete net 10.47.0.0: gateway 192.168.217.1
delete net 10.48.0.0: gateway 192.168.217.1
delete net 10.61.0.0: gateway 192.168.217.1
delete net 192.168.240.0: gateway 192.168.217.1
delete net 192.168.248.0: gateway 192.168.217.1
delete net X.XXX.XXX.XXX: gateway 192.168.217.1
delete net X.XXX.XXX.XX gateway 192.168.217.1
delete net X.XXX.XX.X: gateway 192.168.217.1
delete net X.XXX.XX.XXX: gateway 192.168.217.1
2024-03-05 10:51:03 Closing TUN/TAP interface
2024-03-05 10:51:03 /tmp/pritunl/8d47797dxxxxxxxx-block.sh utun5 1500 0 192.168.217.7 255.255.255.0 init
2024-03-05 10:51:03 SIGTERM[soft,auth-failure] received, process exiting

Server output (server time is 8:50 which is like 10:50 in the VPN logs):

[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: IV_VER=2.5.8
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: IV_PLAT=mac
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: IV_PROTO=6
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: IV_NCP=2
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM:AES-128-CBC
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: IV_LZ4=1
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: IV_LZ4v2=1
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: IV_LZO=1
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: IV_COMP_STUB=1
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: IV_COMP_STUBv2=1
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: IV_TCPNL=1
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: IV_HWADDR=xx:xx:xx:xx:xx:xx
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: IV_SSL=OpenSSL_1.1.1s__1_Nov_2022
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX10094 peer info: UV_ID=72dfc46137e041cd8xxxxxxxxxxxx
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 peer info: UV_NAME=thawing-stars-6898
[summer-dreams-3551] 2024-03-05 08:50:52 XX.XX.XX.XX:10094 [6453591d269xxxxxxxxxx] Peer Connection Initiated with [AF_INET6]::ffff:XX.XX.XX.XX:10094
[summer-dreams-3551] 2024-03-05 08:50:56 COM> SUCCESS: client-kill command succeeded
[summer-dreams-3551] 2024-03-05 08:50:56 User disconnected user_id=6453591d2xxxxxxxxxxxxx
[summer-dreams-3551] 2024-03-05 08:50:56 COM> SUCCESS: client-auth command succeeded
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX:10095 peer info: IV_VER=2.6.8
[summer-dreams-3551] 2024-03-05 08:50:58 ERROR User auth failed "Duplicate nonce"
[summer-dreams-3551] 2024-03-05 08:50:58 COM> SUCCESS: client-deny command succeeded
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX10095 peer info: IV_PLAT=mac
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX:10095 peer info: IV_TCPNL=1
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX:10095 peer info: IV_MTU=1600
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX:10095 peer info: IV_NCP=2
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX10095 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM:CHACHA20-POLY1305:AES-256-CBC:AES-128-CBC
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX:10095 peer info: IV_PROTO=990
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX:10095 peer info: IV_LZO_STUB=1
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX:10095 peer info: IV_COMP_STUB=1
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX:10095 peer info: IV_COMP_STUBv2=1
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX:10095 peer info: IV_HWADDR=xx:xx:xx:xx:xx:xx
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX:10095 peer info: IV_SSL=OpenSSL_3.2.0_23_Nov_2023
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX10095 peer info: UV_ID=34974c5a7e6f43xxxxxxxxxxxxxxxx
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX:10095 peer info: UV_NAME=thawing-meadow-2415
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX:10095 WARNING: 'link-mtu' is used inconsistently, local='link-mtu 1558', remote='link-mtu 1561'
[summer-dreams-3551] 2024-03-05 08:50:58 XX.XX.XX.XX:10095 [6453591d269d8817xxxxxxxx] Peer Connection Initiated with [AF_INET6]::ffff:XX.XX.XX.XX:10095
[summer-dreams-3551] 2024-03-05 08:51:04 MULTI_sva: pool returned IPv4=192.168.217.2, IPv6=(Not enabled)