Frequent disconnections

naman1-gupta · October 7, 2024, 11:18am

I need help with troubleshooting frequent disconnections. We have had an enterprise license and a simple setup with a single host running pritunl version v1.29.x for some time now. Few months back, our users started reporting frequent disconnections.

At first, we tried upgrading the version of pritunl to ensure that wasn’t the case, but that doesn’t seem to have changed things.

I enabled debug output on the affected server to find client-kill is issued every 2 minute 30 seconds. I’m not sure of the reason, but this is happening to every single user connected to this instance of pritunl.

10:23:19 User connected user_id=63a993bf7ed7d5001270b92c
[staging-vpn-01] 2024-10-07 10:25:50 COM> SUCCESS: client-kill command succeeded
[staging-vpn-01] 2024-10-07 10:25:50 User disconnected user_id=63a993bf7ed7d5001270b92c
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: IV_VER=2.6.8
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: IV_PLAT=mac
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: IV_TCPNL=1
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: IV_MTU=1600
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: IV_NCP=2
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM:CHACHA20-POLY1305:AES-256-CBC:AES-128-CBC
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: IV_PROTO=990
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: IV_LZO_STUB=1
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: IV_COMP_STUB=1
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: IV_COMP_STUBv2=1
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: IV_HWADDR=XXXXXXXXXXX
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: IV_SSL=OpenSSL_3.2.0_23_Nov_2023
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: UV_ID=37163609f0e34adcb3e7c4fb09425bfe
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 peer info: UV_NAME=patient-waterfall-9261
[staging-vpn-01] 2024-10-07 10:25:51 122.171.19.191:10872 [63a993bf7ed7d5001270b92c] Peer Connection Initiated with [AF_INET6]::ffff:122.171.19.191:10872
[staging-vpn-01] 2024-10-07 10:25:52 read UDPv6 [ECONNREFUSED]: Connection refused (fd=5,code=111)
[staging-vpn-01] 2024-10-07 10:25:52 COM> SUCCESS: client-auth command succeeded
[staging-vpn-01] 2024-10-07 10:25:52 MULTI_sva: pool returned IPv4=192.168.234.2, IPv6=(Not enabled)
[staging-vpn-01] 2024-10-07 10:25:52 User connected user_id=63a993bf7ed7d5001270b92c
[staging-vpn-01] 2024-10-07 10:28:22 COM> SUCCESS: client-kill command succeeded
[staging-vpn-01] 2024-10-07 10:28:22 User disconnected user_id=63a993bf7ed7d5001270b92c
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: IV_VER=2.6.8
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: IV_PLAT=mac
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: IV_TCPNL=1
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: IV_MTU=1600
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: IV_NCP=2
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM:CHACHA20-POLY1305:AES-256-CBC:AES-128-CBC
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: IV_PROTO=990
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: IV_LZO_STUB=1
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: IV_COMP_STUB=1
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: IV_COMP_STUBv2=1
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: IV_HWADDR=XXXXXXXX
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: IV_SSL=OpenSSL_3.2.0_23_Nov_2023
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: UV_ID=37163609f0e34adcb3e7c4fb09425bfe
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 peer info: UV_NAME=patient-waterfall-9261
[staging-vpn-01] 2024-10-07 10:28:23 122.171.19.191:22744 [63a993bf7ed7d5001270b92c] Peer Connection Initiated with [AF_INET6]::ffff:122.171.19.191:22744

In another test, I disconnected this host from the first instance and created another mongo instance for it to connect to, and the same issue was not observed. Does anyone have any insights on how to debug this further?

Verbose server logs

2024-10-07 11:22:41 Server conf:
2024-10-07 11:22:41   ignore-unknown-option ncp-ciphers
2024-10-07 11:22:41   port 10415
2024-10-07 11:22:41   proto udp6
2024-10-07 11:22:41   dev tun4
2024-10-07 11:22:41   server 192.168.234.0 255.255.255.0
2024-10-07 11:22:41   management /var/run/pritunl_6703c481ec563a5e21ab6924.sock unix
2024-10-07 11:22:41   management-client-auth
2024-10-07 11:22:41   auth-user-pass-optional
2024-10-07 11:22:41   topology subnet
2024-10-07 11:22:41   tls-version-min 1.2
2024-10-07 11:22:41   max-clients 2000
2024-10-07 11:22:41   ping 10
2024-10-07 11:22:41   ping-restart 80
2024-10-07 11:22:41   persist-tun
2024-10-07 11:22:41   cipher AES-128-CBC
2024-10-07 11:22:41   ncp-ciphers AES-128-GCM:AES-128-CBC
2024-10-07 11:22:41   auth SHA1
2024-10-07 11:22:41   status-version 2
2024-10-07 11:22:41   script-security 2
2024-10-07 11:22:41   sndbuf 393216
2024-10-07 11:22:41   rcvbuf 393216
2024-10-07 11:22:41   reneg-sec 2592000
2024-10-07 11:22:41   hash-size 1024 1024
2024-10-07 11:22:41   txqueuelen 1000
2024-10-07 11:22:41   verb 4
2024-10-07 11:22:41   mute 8
2024-10-07 11:22:41   client-to-client
2024-10-07 11:22:41   replay-window 128
2024-10-07 11:22:41   max-routes-per-client 1024
2024-10-07 11:22:41   ignore-unknown-option allow-compression
2024-10-07 11:22:41   allow-compression no
2024-10-07 11:22:41   comp-lzo no
2024-10-07 11:22:41   push "comp-lzo no"
2024-10-07 11:22:41   push "route 10.0.0.0 255.255.0.0"
2024-10-07 11:22:41 Note: Treating option '--ncp-ciphers' as  '--data-ciphers' (renamed in OpenVPN 2.5).
2024-10-07 11:22:41 us=964119 Note: '--allow-compression' is not set to 'no', disabling data channel offload.
2024-10-07 11:22:41 us=964133 Consider using the '--compress migrate' option.
2024-10-07 11:22:41 us=964145 Current Parameter Settings:
2024-10-07 11:22:41 us=964151   config = '/tmp/pritunl_83f2585c6e4e41f49aeefe0a2ecbc7e7/1e8b107734f14c53bf9d004922c8b60e/openvpn.conf'
2024-10-07 11:22:41 us=964156 NOTE: --mute triggered...
2024-10-07 11:22:41 us=964167 294 variation(s) on previous 8 message(s) suppressed by --mute
2024-10-07 11:22:41 us=964172 OpenVPN 2.6.12 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [AEAD] [DCO]
2024-10-07 11:22:41 us=964183 library versions: OpenSSL 3.0.2 15 Mar 2022, LZO 2.10
2024-10-07 11:22:41 us=964206 DCO version: N/A
2024-10-07 11:22:41 us=964285 MANAGEMENT: unix domain socket listening on /var/run/pritunl_6703c481ec563a5e21ab6924.sock
2024-10-07 11:22:41 us=964404 net_route_v4_best_gw query: dst 0.0.0.0
2024-10-07 11:22:41 us=964484 net_route_v4_best_gw result: via 10.0.4.1 dev ens5
2024-10-07 11:22:41 us=966166 Diffie-Hellman initialized with 2048 bit key
2024-10-07 11:22:41 us=968528 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2024-10-07 11:22:41 us=968545 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2024-10-07 11:22:41 us=968575 TLS-Auth MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1250 tun_max_mtu:0 headroom:126 payload:1600 tailroom:126 ET:0 ]
2024-10-07 11:22:41 us=969002 TUN/TAP device tun4 opened
2024-10-07 11:22:41 us=969051 TUN/TAP TX queue length set to 1000
2024-10-07 11:22:41 us=969087 do_ifconfig, ipv4=1, ipv6=0
2024-10-07 11:22:41 us=969102 net_iface_mtu_set: mtu 1500 for tun4
2024-10-07 11:22:41 us=969139 net_iface_up: set tun4 up
2024-10-07 11:22:41 us=969233 net_addr_v4_add: 192.168.234.1/24 dev tun4
2024-10-07 11:22:41 us=969291 Data Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
2024-10-07 11:22:41 us=969309 Socket Buffers: R=[212992->425984] S=[212992->425984]
2024-10-07 11:22:41 us=969314 setsockopt(IPV6_V6ONLY=0)
2024-10-07 11:22:41 us=969327 UDPv6 link local (bound): [AF_INET6][undef]:10415
2024-10-07 11:22:41 us=969333 UDPv6 link remote: [AF_UNSPEC]
2024-10-07 11:22:41 us=969353 MULTI: multi_init called, r=1024 v=1024
2024-10-07 11:22:41 us=969394 IFCONFIG POOL IPv4: base=192.168.234.2 size=253
2024-10-07 11:22:41 us=969428 Initialization Sequence Completed
2024-10-07 11:22:42 us=307666 MANAGEMENT: Client connected from /var/run/pritunl_6703c481ec563a5e21ab6924.sock
2024-10-07 11:22:43 us=308825 MANAGEMENT: CMD 'bytecount 15'
2024-10-07 11:22:43 COM> SUCCESS: bytecount interval changed
2024-10-07 11:23:19 us=413623 Connection Attempt MULTI: multi_create_instance called
2024-10-07 11:23:19 us=413666 122.171.19.191:23253 Re-using SSL/TLS context
2024-10-07 11:23:19 us=413734 122.171.19.191:23253 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2024-10-07 11:23:19 us=413745 122.171.19.191:23253 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2024-10-07 11:23:19 us=413902 122.171.19.191:23253 Control Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1250 tun_max_mtu:0 headroom:126 payload:1600 tailroom:126 ET:0 ]
2024-10-07 11:23:19 us=413913 122.171.19.191:23253 Data Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
2024-10-07 11:23:20 us=120311 122.171.19.191:23253 PID_ERR replay-window backtrack occurred [1] [TLS_WRAP-0] [0_000111_] 1728300199:9 1728300199:8 t=1728300200[0] r=[-1,128,15,1,1] sl=[119,9,128,1040]
2024-10-07 11:23:20 us=121306 122.171.19.191:23253 VERIFY OK: depth=1, O=5d1f1af07ed7d50012972b69, CN=5d1f1af07ed7d50012972b70
2024-10-07 11:23:20 us=121489 122.171.19.191:23253 VERIFY OK: depth=0, O=5d1f1af07ed7d50012972b69, CN=63a993bf7ed7d5001270b92c
2024-10-07 11:23:20 us=121823 122.171.19.191:23253 peer info: IV_VER=2.6.8
2024-10-07 11:23:20 us=121839 122.171.19.191:23253 peer info: IV_PLAT=mac
2024-10-07 11:23:20 us=121846 122.171.19.191:23253 peer info: IV_TCPNL=1
2024-10-07 11:23:20 us=121852 122.171.19.191:23253 peer info: IV_MTU=1600
2024-10-07 11:23:20 us=121857 122.171.19.191:23253 peer info: IV_NCP=2
2024-10-07 11:23:20 us=121863 122.171.19.191:23253 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM:CHACHA20-POLY1305:AES-256-CBC:AES-128-CBC
2024-10-07 11:23:20 us=121869 122.171.19.191:23253 peer info: IV_PROTO=990
2024-10-07 11:23:20 us=121874 122.171.19.191:23253 peer info: IV_LZO_STUB=1
2024-10-07 11:23:20 us=121879 122.171.19.191:23253 peer info: IV_COMP_STUB=1
2024-10-07 11:23:20 us=121885 122.171.19.191:23253 peer info: IV_COMP_STUBv2=1
2024-10-07 11:23:20 us=121892 122.171.19.191:23253 peer info: IV_HWADDR=XXXXXXXXXXXXXX
2024-10-07 11:23:20 us=121898 122.171.19.191:23253 peer info: IV_SSL=OpenSSL_3.2.0_23_Nov_2023
2024-10-07 11:23:20 us=121904 122.171.19.191:23253 peer info: UV_ID=4d8966dd55894acb9bca540e45617f0a
2024-10-07 11:23:20 us=121909 122.171.19.191:23253 peer info: UV_NAME=summer-stars-4973
2024-10-07 11:23:20 us=121986 122.171.19.191:23253 TLS: Username/Password authentication deferred for username '' 
2024-10-07 11:23:20 us=122005 122.171.19.191:23253 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
2024-10-07 11:23:20 us=122073 122.171.19.191:23253 NOTE: --mute triggered...
2024-10-07 11:23:20 us=150234 122.171.19.191:23253 2 variation(s) on previous 8 message(s) suppressed by --mute
2024-10-07 11:23:20 us=150247 122.171.19.191:23253 [63a993bf7ed7d5001270b92c] Peer Connection Initiated with [AF_INET6]::ffff:122.171.19.191:23253
2024-10-07 11:23:21 Client conf 63a993bf7ed7d5001270b92c:
2024-10-07 11:23:21   push "ping 10"
2024-10-07 11:23:21   push "ping-restart 60"
2024-10-07 11:23:21   push "dhcp-option DNS 1.1.1.1"
2024-10-07 11:23:21   ifconfig-push 192.168.234.120 255.255.255.0
2024-10-07 11:23:21 us=365739 MANAGEMENT: CMD 'client-auth 0 1'
2024-10-07 11:23:21 COM> SUCCESS: client-auth command succeeded
2024-10-07 11:23:21 us=432287 122.171.19.191:23253 PUSH: Received control message: 'PUSH_REQUEST'
2024-10-07 11:23:21 User connected user_id=63a993bf7ed7d5001270b92c
2024-10-07 11:23:21 us=432315 63a993bf7ed7d5001270b92c/122.171.19.191:23253 MULTI_sva: pool returned IPv4=192.168.234.2, IPv6=(Not enabled)
2024-10-07 11:23:21 us=432388 63a993bf7ed7d5001270b92c/122.171.19.191:23253 MULTI: Learn: 192.168.234.120 -> 63a993bf7ed7d5001270b92c/122.171.19.191:23253
2024-10-07 11:23:21 us=432400 63a993bf7ed7d5001270b92c/122.171.19.191:23253 MULTI: primary virtual IP for 63a993bf7ed7d5001270b92c/122.171.19.191:23253: 192.168.234.120
2024-10-07 11:23:21 us=432431 63a993bf7ed7d5001270b92c/122.171.19.191:23253 Data Channel MTU parms [ mss_fix:1379 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
2024-10-07 11:23:21 us=432509 63a993bf7ed7d5001270b92c/122.171.19.191:23253 Outgoing dynamic tls-crypt: Cipher 'AES-256-CTR' initialized with 256 bit key
2024-10-07 11:23:21 us=432531 63a993bf7ed7d5001270b92c/122.171.19.191:23253 Outgoing dynamic tls-crypt: Using 256 bit message hash 'SHA256' for HMAC authentication
2024-10-07 11:23:21 us=432540 63a993bf7ed7d5001270b92c/122.171.19.191:23253 NOTE: --mute triggered...
2024-10-07 11:23:21 us=432615 63a993bf7ed7d5001270b92c/122.171.19.191:23253 4 variation(s) on previous 8 message(s) suppressed by --mute
2024-10-07 11:23:21 us=432626 63a993bf7ed7d5001270b92c/122.171.19.191:23253 SENT CONTROL [63a993bf7ed7d5001270b92c]: 'PUSH_REPLY,comp-lzo no,route 10.0.0.0 255.255.0.0,route-gateway 192.168.234.1,topology subnet,ping 10,ping-restart 60,dhcp-option DNS 1.1.1.1,ifconfig 192.168.234.120 255.255.255.0,peer-id 0,cipher AES-128-GCM,protocol-flags cc-exit tls-ekm dyn-tls-crypt,tun-mtu 1500' (status=1)
2024-10-07 11:23:22 us=948952 63a993bf7ed7d5001270b92c/122.171.19.191:23253 Data Channel: cipher 'AES-128-GCM', peer-id: 0, compression: 'stub'
2024-10-07 11:23:22 us=948972 63a993bf7ed7d5001270b92c/122.171.19.191:23253 Timers: ping 10, ping-restart 80
2024-10-07 11:23:22 us=948980 63a993bf7ed7d5001270b92c/122.171.19.191:23253 NOTE: --mute triggered...
2024-10-07 11:23:28 us=568757 63a993bf7ed7d5001270b92c/122.171.19.191:23253 1 variation(s) on previous 8 message(s) suppressed by --mute
2024-10-07 11:23:28 us=568773 63a993bf7ed7d5001270b92c/122.171.19.191:23253 PID_ERR replay-window backtrack occurred [4] [SSL-0] [00_0_1111] 0:9 0:5 t=1728300208[0] r=[-1,128,15,4,1] sl=[119,9,128,1040]
2024-10-07 11:25:51 us=586647 MANAGEMENT: CMD 'client-kill 0'
2024-10-07 11:25:51 COM> SUCCESS: client-kill command succeeded
2024-10-07 11:25:51 User disconnected user_id=63a993bf7ed7d5001270b92c
2024-10-07 11:25:51 us=586671 Delayed exit in 5 seconds
2024-10-07 11:25:51 us=586697 SENT CONTROL [63a993bf7ed7d5001270b92c]: 'RESTART' (status=1)
2024-10-07 11:25:52 us=788284 Connection Attempt MULTI: multi_create_instance called
2024-10-07 11:25:52 us=788321 122.171.19.191:30843 Re-using SSL/TLS context
2024-10-07 11:25:52 us=788383 122.171.19.191:30843 Outgoing Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2024-10-07 11:25:52 us=788395 122.171.19.191:30843 Incoming Control Channel Authentication: Using 160 bit message hash 'SHA1' for HMAC authentication
2024-10-07 11:25:52 us=788534 122.171.19.191:30843 Control Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1250 tun_max_mtu:0 headroom:126 payload:1600 tailroom:126 ET:0 ]
2024-10-07 11:25:52 us=788545 122.171.19.191:30843 Data Channel MTU parms [ mss_fix:0 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
2024-10-07 11:25:52 us=926508 122.171.19.191:30843 PID_ERR replay-window backtrack occurred [2] [TLS_WRAP-0] [0__00000_] 1728300352:9 1728300352:7 t=1728300352[0] r=[0,128,15,2,1] sl=[119,9,128,1040]
2024-10-07 11:25:52 us=927503 122.171.19.191:30843 VERIFY OK: depth=1, O=5d1f1af07ed7d50012972b69, CN=5d1f1af07ed7d50012972b70
2024-10-07 11:25:52 us=927694 122.171.19.191:30843 VERIFY OK: depth=0, O=5d1f1af07ed7d50012972b69, CN=63a993bf7ed7d5001270b92c
2024-10-07 11:25:52 us=927967 122.171.19.191:30843 peer info: IV_VER=2.6.8
2024-10-07 11:25:52 us=927981 122.171.19.191:30843 peer info: IV_PLAT=mac
2024-10-07 11:25:52 us=927987 122.171.19.191:30843 peer info: IV_TCPNL=1
2024-10-07 11:25:52 us=927992 122.171.19.191:30843 peer info: IV_MTU=1600
2024-10-07 11:25:52 us=927998 122.171.19.191:30843 peer info: IV_NCP=2
2024-10-07 11:25:52 us=928004 122.171.19.191:30843 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM:CHACHA20-POLY1305:AES-256-CBC:AES-128-CBC
2024-10-07 11:25:52 us=928009 122.171.19.191:30843 peer info: IV_PROTO=990
2024-10-07 11:25:52 us=928014 122.171.19.191:30843 peer info: IV_LZO_STUB=1
2024-10-07 11:25:52 us=928038 122.171.19.191:30843 peer info: IV_COMP_STUB=1
2024-10-07 11:25:52 us=928044 122.171.19.191:30843 peer info: IV_COMP_STUBv2=1
2024-10-07 11:25:52 us=928050 122.171.19.191:30843 peer info: IV_HWADDR=XXXXXXXXXXXXXX
2024-10-07 11:25:52 us=928056 122.171.19.191:30843 peer info: IV_SSL=OpenSSL_3.2.0_23_Nov_2023
2024-10-07 11:25:52 us=928062 122.171.19.191:30843 peer info: UV_ID=4d8966dd55894acb9bca540e45617f0a
2024-10-07 11:25:52 us=928067 122.171.19.191:30843 peer info: UV_NAME=summer-stars-4973
2024-10-07 11:25:52 us=928150 122.171.19.191:30843 TLS: Username/Password authentication deferred for username '' 
2024-10-07 11:25:52 us=928196 122.171.19.191:30843 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
2024-10-07 11:25:52 us=928242 122.171.19.191:30843 NOTE: --mute triggered...
2024-10-07 11:25:53 us=51437 122.171.19.191:30843 2 variation(s) on previous 8 message(s) suppressed by --mute
2024-10-07 11:25:53 us=51451 122.171.19.191:30843 [63a993bf7ed7d5001270b92c] Peer Connection Initiated with [AF_INET6]::ffff:122.171.19.191:30843
2024-10-07 11:25:53 us=310124 122.171.19.191:30843 PUSH: Received control message: 'PUSH_REQUEST'
2024-10-07 11:25:53 us=890107 read UDPv6 [ECONNREFUSED]: Connection refused (fd=5,code=111)
2024-10-07 11:25:54 Client conf 63a993bf7ed7d5001270b92c:
2024-10-07 11:25:54   push "ping 10"
2024-10-07 11:25:54   push "ping-restart 60"
2024-10-07 11:25:54   push "dhcp-option DNS 1.1.1.1"
2024-10-07 11:25:54   ifconfig-push 192.168.234.120 255.255.255.0
2024-10-07 11:25:54 us=232939 MANAGEMENT: CMD 'client-auth 1 1'
2024-10-07 11:25:54 COM> SUCCESS: client-auth command succeeded
2024-10-07 11:25:54 us=404212 MULTI: new connection by client '63a993bf7ed7d5001270b92c' will cause previous active sessions by this client to be dropped.  Remember to use the --duplicate-cn option if you want multiple clients using the same certificate or username to concurrently connect.
2024-10-07 11:25:54 User connected user_id=63a993bf7ed7d5001270b92c
2024-10-07 11:25:54 us=404231 MULTI_sva: pool returned IPv4=192.168.234.2, IPv6=(Not enabled)
2024-10-07 11:25:54 us=404300 MULTI: Learn: 192.168.234.120 -> 63a993bf7ed7d5001270b92c/122.171.19.191:30843
2024-10-07 11:25:54 us=404311 MULTI: primary virtual IP for 63a993bf7ed7d5001270b92c/122.171.19.191:30843: 192.168.234.120
2024-10-07 11:25:54 us=404340 Data Channel MTU parms [ mss_fix:1379 max_frag:0 tun_mtu:1500 tun_max_mtu:1600 headroom:136 payload:1768 tailroom:562 ET:0 ]
2024-10-07 11:25:54 us=404390 Outgoing dynamic tls-crypt: Cipher 'AES-256-CTR' initialized with 256 bit key
2024-10-07 11:25:54 us=404409 Outgoing dynamic tls-crypt: Using 256 bit message hash 'SHA256' for HMAC authentication
2024-10-07 11:25:54 us=404417 NOTE: --mute triggered...
2024-10-07 11:25:54 us=404487 4 variation(s) on previous 8 message(s) suppressed by --mute
2024-10-07 11:25:54 us=404496 SENT CONTROL [63a993bf7ed7d5001270b92c]: 'PUSH_REPLY,comp-lzo no,route 10.0.0.0 255.255.0.0,route-gateway 192.168.234.1,topology subnet,ping 10,ping-restart 60,dhcp-option DNS 1.1.1.1,ifconfig 192.168.234.120 255.255.255.0,peer-id 1,cipher AES-128-GCM,protocol-flags cc-exit tls-ekm dyn-tls-crypt,tun-mtu 1500' (status=1)
2024-10-07 11:25:55 us=215675 63a993bf7ed7d5001270b92c/122.171.19.191:30843 Data Channel: cipher 'AES-128-GCM', peer-id: 0, compression: 'stub'
2024-10-07 11:25:55 us=215694 63a993bf7ed7d5001270b92c/122.171.19.191:30843 Timers: ping 10, ping-restart 80
2024-10-07 11:25:55 us=215701 63a993bf7ed7d5001270b92c/122.171.19.191:30843 NOTE: --mute triggered...

zach · October 7, 2024, 11:37pm

Check the logs for errors in the top right of the web console on the server.

naman1-gupta · October 8, 2024, 1:44am

There is nothing in those logs to suggest why this might be happening

[lively-waves-7409][2024-10-08 01:41:19,057][ERROR] Client lost unexpectedly
  instance_id = "67048d267ed7d50012fa0df3"
  server_id   = "66857de07ed7d50012a5829d"
Traceback (most recent call last):
  File "/usr/lib64/python2.7/threading.py", line 785, in __bootstrap
    self.__bootstrap_inner()
  File "/usr/lib64/python2.7/threading.py", line 812, in __bootstrap_inner
    self.run()
  File "/usr/lib64/python2.7/threading.py", line 765, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/pritunl/lib/python2.7/site-packages/pritunl/helpers.py", line 39, in _wrapped
    for _ in call(*args, **kwargs):
  File "/usr/lib/pritunl/lib/python2.7/site-packages/pritunl/clients/clients.py", line 1465, in ping_thread
    instance_id=self.instance.id,
  File "/usr/lib/pritunl/lib/python2.7/site-packages/pritunl/logger/__init__.py", line 55, in error
    kwargs['traceback'] = traceback.format_stack()
[lively-waves-7409][2024-10-08 01:41:19,860][INFO] Bypass secondary enabled, skipping password
  org_name    = "XXXXXXXXXXXXXX"
  user_name   = "XXXXXXXXXXXXXXXXXXXXXX"
  server_name = "XXXXXXXXXXX"
[lively-waves-7409][2024-10-08 01:41:23,116][ERROR] Client lost unexpectedly
  instance_id = "67048d267ed7d50012fa0df3"
  server_id   = "66857de07ed7d50012a5829d"
Traceback (most recent call last):
  File "/usr/lib64/python2.7/threading.py", line 785, in __bootstrap
    self.__bootstrap_inner()
  File "/usr/lib64/python2.7/threading.py", line 812, in __bootstrap_inner
    self.run()
  File "/usr/lib64/python2.7/threading.py", line 765, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/usr/lib/pritunl/lib/python2.7/site-packages/pritunl/helpers.py", line 39, in _wrapped
    for _ in call(*args, **kwargs):
  File "/usr/lib/pritunl/lib/python2.7/site-packages/pritunl/clients/clients.py", line 1465, in ping_thread
    instance_id=self.instance.id,
  File "/usr/lib/pritunl/lib/python2.7/site-packages/pritunl/logger/__init__.py", line 55, in error
    kwargs['traceback'] = traceback.format_stack()

zach · October 9, 2024, 9:02pm

The Client lost unexpectedly will occur when the client record is expired from the database. This will occur if the server loses connectivity to the database for an extended time or the server locks up and isn’t able to update the record before it expires. Verify there are no connectivity issues to the database and that the server has sufficient resources.

The command sudo pritunl set vpn.client_ttl 600 can be run to increase this timeout. At least one host will need to be restarted after running this to update the database indexes.

naman1-gupta · October 15, 2024, 9:09am

Earlier, the client_ttl was set as 300 and the users would disconnect at exactly half of that time, i.e., 2 mins 30 secs. I set it to a higher value and I can reproduce the same issue. For a TTL of 600 seconds, the users get disconnected after exactly 5mins.

The connectivity between the db and the pritunl hosts seem fine, and the hosts themselves are mostly running idle. I tried profiling the mongodb database and the only remove commands on the pritunl.clients came from the pritunl host itself trying to clean up with the nReturned value of 0.

Do you have any suggestions on how to debug this further?

zach · October 15, 2024, 10:14am

If single sign-on is configured it could be the authentication checking. Reduce the frequency by running sudo pritunl set app.sso_connection_check_ttl 7200 or disable it by running sudo pritunl set app.sso_connection_check false.

It’s very likely this is a resource issue with the server monitor the CPU and memory usage. It’s also possible the datetime is incorrect on one of the hosts or the database server.