search

OpenVPN / ovpn-dco

OpenVPN Data Channel Offload in the linux kernel
106 stars 26 forks source link

DEL_PEER not delivered to userspace: netlink returns NLE_AGAIN #37

Closed atoy40 closed 9 months ago

atoy40 commented 1 year ago

Hi,

I'm testing openvpn 2.6 + DCO on a Debian Bullseye:

ii  openvpn                              2.6.4-bullseye0                amd64        virtual private network daemon
ii  openvpn-dco-dkms                     0.2.20230426-bullseye0         all          DCO (Data-Channel Offload) kernel module for OpenVPN)

This is a multi-user (UDP) setup and I'd like to clarify the behavior when a client disconnects.

As soon as a client disconnect, the server (userspace) process start to log "read UDPv4" errors. Then, I can see 2 behaviors.

sometimes, I've a ping expired :

May 16 16:35:41 vpn-otp openvpn[7952]: userxxx/10.8.22.175:50600 SIGTERM[soft,ovpn-dco: ping expired] received, client-instance exiting
May 16 16:35:41 vpn-otp kernel: [ 3634.184984] tunuppa: deleting peer with id 0, reason 2

but sometimes, there is a netlink error :

May 16 17:55:54 vpn-otp openvpn[14002]: dco_do_read: netlink reports error (-4): Try again
May 16 17:55:54 vpn-otp kernel: [ 8446.943728] tunuppa: deleting peer with id 0, reason 2

in this second case, the user is still "connected" on the server, then it is removed later by the tls_multi_process :

May 22 11:36:09 vpn-otp openvpn[63605]: userxxx/10.8.23.133:55261 TLS: tls_multi_process: killed expiring key
May 22 11:36:09 vpn-otp openvpn[63605]: userxxx/10.8.23.133:55261 No encryption key found. Purging data channel keys
May 22 11:36:09 vpn-otp openvpn[63605]: userxxx/10.8.23.133:55261 dco_del_key: netlink reports object not found, ovpn-dco unloaded?
May 22 11:36:09 vpn-otp openvpn[63605]: userxxx/10.8.23.133:55261 dco_del_key: failed to send netlink message: No such file or directory (-2)
May 22 11:36:09 vpn-otp openvpn[63605]: userxxx/10.8.23.133:55261 Cannot delete primary key during wipe: No such file or directory (-2)
May 22 11:36:09 vpn-otp openvpn[63605]: userxxx/10.8.23.133:55261 SIGUSR1[soft,dco update keys error] received, client-instance restarting
May 22 11:36:09 vpn-otp openvpn[63605]: dco_del_peer: netlink reports object not found, ovpn-dco unloaded?
May 22 11:36:09 vpn-otp openvpn[63605]: dco_del_peer: failed to send netlink message: No such file or directory (-2)

I tried to define the explicit-exit-notify on both server and client, but I'm not sure it has any effect.

Is it possible to help me to clarify how to properly handle client disconnections (and avoid the server to keep references of disconnected clients too long)

Thanks for help

Anthony.

ordex commented 1 year ago

Hi Anthony,

the standard proper way is to have the ping/keepalive configured and let it detect disconnected UDP clients. Your second case is weird - basically the disconnection notification is delivered to userspace which has issues reading it. I have never seen this specific behaviour/error.

Do you have any steps for me to reproduce it? Maybe you noted something specific that you or the client need to do in order to trigger that problem?

atoy40 commented 1 year ago

@ordex the client I'm using to test is mainly OpenVPN Connect 3.3.4 on Android, but I've also tested with the linux openvpn3 client and noted the same behavior. The second case (netlink error -4) orccurs way more often than the "proper" ping expired.

Nothing really specific in my setup, the only thing is may be the management-client-auth (and no client certs), but it works as excpected.

Here is my test server config (notthing really specific in client config) :

port 1194
proto udp
dev tunuppa
management 127.0.0.1 8000
dh uppa/dh4096.pem
ca uppa/rootCA.crt
cert uppa/server.crt
key uppa/server.key
tls-auth uppa/tls-auth-shared.key 0
keepalive 10 60
explicit-exit-notify
persist-key
persist-tun
status uppa/openvpn-status.log 2
verb 3

# Auth
management-client-auth
verify-client-cert none
username-as-common-name
duplicate-cn

# Network
mode server
tls-server
topology subnet
ifconfig 10.10.14.1 255.255.254.0
ifconfig-pool 10.10.14.2 10.10.15.254 255.255.254.0

# Client config
push "topology subnet"
push "route-gateway 10.10.14.1"
push "redirect-gateway def1"
push "dhcp-option DNS x.x.x.x"
push "dhcp-option DOMAIN xxx.fr"
push "block-outside-dns"
push "persist-tun"
push "persist-key"
push "explicit-exit-notify"

kernel version is 5.10.0-22 x86_64 from Debian.

Thanks for help. Anthony

ordex commented 1 year ago

Thanks! Can you please share a longer log rather than just those two lines? I'd like to see if something else is happening which might be the cause for that error later on.

atoy40 commented 1 year ago

Here is a resume of events :

Hope this can help.

full log :

May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 peer info: IV_VER=3.git::081bfebe:RelWithDebInfo
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 peer info: IV_PLAT=android
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 peer info: IV_NCP=2
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 peer info: IV_TCPNL=1
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 peer info: IV_PROTO=30
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 peer info: IV_CIPHERS=AES-256-GCM:AES-128-GCM:CHACHA20-POLY1305:BF-CBC
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 peer info: IV_GUI_VER=net.openvpn.connect.android_3.3.4-9290
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 peer info: IV_SSO=webauth,openurl,crtext
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 peer info: IV_BS64DL=1
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 TLS: Username/Password authentication deferred for username 'testuser' [CN SET]
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 TLS: move_session: dest=TM_ACTIVE src=TM_INITIAL reinit_src=1
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 TLS: tls_multi_process: initial untrusted session promoted to semi-trusted
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 Control Channel: TLSv1.3, cipher TLSv1.3 TLS_AES_256_GCM_SHA384
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 [testuser] Peer Connection Initiated with [AF_INET]10.8.23.133:53401
May 22 14:41:15 vpn-otp openvpn[70797]: 10.8.23.133:53401 PUSH: Received control message: 'PUSH_REQUEST'
May 22 14:41:15 vpn-otp openvpn[70797]: MANAGEMENT: CMD 'client-auth 0 1'
May 22 14:41:16 vpn-otp openvpn[70797]: 10.8.23.133:53401 PUSH: Received control message: 'PUSH_REQUEST'
May 22 14:41:16 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 MULTI_sva: pool returned IPv4=10.10.14.2, IPv6=(Not enabled)
May 22 14:41:16 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 MULTI: Learn: 10.10.14.2 -> testuser/10.8.23.133:53401
May 22 14:41:16 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 MULTI: primary virtual IP for testuser/10.8.23.133:53401: 10.10.14.2
May 22 14:41:16 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 SENT CONTROL [testuser]: 'PUSH_REPLY,topology subnet,route-gateway 10.10.14.1,redirect-gateway def1,dhcp-option DNS 194.167.156.13,dhcp-option DOMAIN xxxx.fr,block-outside-dns,persist-tun,persist-key,explicit-exit-notify,ping 10,ping-restart 60,auth-token,ifconfig 10.10.14.2 255.255.254.0,peer-id 0,cipher AES-256-GCM,key-derivation tls-ekm' (status=1)
May 22 14:41:17 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 Data Channel: cipher 'AES-256-GCM', peer-id: 0
May 22 14:41:17 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 Timers: ping 10, ping-restart 120
May 22 14:41:17 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 Protocol options: explicit-exit-notify 1, protocol-flags tls-ekm
May 22 14:41:59 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:41:59 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:41:59 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:41:59 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:41:59 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:41:59 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:00 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:02 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:04 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:10 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:20 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:20 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:31 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:41 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:41 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:50 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED|ECONNREFUSED|ECONNREFUSED|ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:51 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:53 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:55 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:42:59 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:43:08 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:43:25 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:43:55 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 14:44:00 vpn-otp openvpn[70797]: dco_do_read: netlink reports error (-4): Try again
May 22 14:44:00 vpn-otp kernel: [429330.017486] tunuppa: deleting peer with id 0, reason 2
May 22 15:39:13 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:39:15 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:39:19 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:39:28 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:39:43 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:40:13 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:40:13 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:40:13 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1
May 22 15:40:13 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:40:15 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:40:19 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:40:44 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:41:13 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:41:13 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:41:28 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:41:31 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:41:35 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:41:59 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:42:28 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:42:28 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:42:44 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:42:50 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:43:14 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:43:43 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:43:43 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:43:59 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:44:01 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:44:05 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:44:13 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:44:29 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:44:58 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:44:58 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:45:16 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:45:28 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:46:15 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:46:15 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:46:32 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:47:01 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:47:31 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:47:31 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:47:46 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:47:48 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:47:52 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:48:00 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:48:16 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:48:46 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:48:46 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:49:02 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:49:08 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:49:16 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:49:33 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:50:02 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:50:02 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:50:17 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:50:19 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:50:23 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:50:31 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:50:48 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:51:18 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:51:18 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:51:35 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:51:39 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:51:48 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:52:33 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:52:33 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:52:48 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:52:50 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:52:55 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:53:03 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:53:18 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:53:48 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:53:48 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:54:03 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:54:05 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:54:09 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:55:03 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:55:03 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:55:19 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:55:21 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:55:25 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:55:33 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:55:49 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:56:19 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:56:19 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:56:34 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:56:36 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:56:40 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:56:48 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:57:05 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:57:34 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:57:34 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:57:49 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:57:51 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:57:56 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:58:04 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:58:20 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:58:50 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 15:58:50 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 15:59:05 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:59:07 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:59:12 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:59:20 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 15:59:36 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:00:05 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:00:05 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:00:20 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:00:22 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:00:27 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:00:35 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:00:51 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:01:20 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:01:20 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:01:36 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:01:38 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:01:42 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:02:06 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:02:35 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:02:35 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:02:51 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:02:57 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:03:51 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:03:51 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:04:06 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:04:12 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:05:06 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:05:06 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:05:21 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:05:28 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:06:21 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:06:21 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:06:36 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:06:51 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:07:36 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:07:36 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:07:51 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:07:53 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:07:58 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:08:06 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:08:22 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:08:52 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:08:52 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:09:07 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:09:22 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:10:07 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:10:07 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:10:22 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:10:29 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:11:22 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:11:22 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:11:37 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:11:43 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:12:37 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:12:37 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:12:52 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:12:54 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:12:58 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:13:06 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:13:23 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:13:52 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:13:52 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:14:13 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:14:38 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:15:07 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:15:07 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:15:24 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:15:37 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:16:22 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:16:22 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:16:40 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:16:52 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:17:08 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:17:37 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:17:37 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:17:52 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:17:54 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:17:58 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:18:07 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:18:23 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:18:52 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:18:52 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:19:07 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:19:10 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:19:14 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:19:38 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:20:07 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:20:07 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:20:29 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:21:22 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:21:22 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:21:38 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:21:40 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:21:44 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:21:52 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:22:08 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:22:38 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:22:38 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:22:54 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:22:56 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:23:00 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:23:08 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:23:25 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:23:53 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:23:53 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:24:08 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:24:10 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:24:14 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:25:08 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:25:08 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:25:23 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:25:37 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:26:24 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:26:24 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:26:39 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:26:46 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:27:09 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:27:39 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:27:39 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:27:54 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:27:56 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:28:00 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:28:08 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:28:25 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:28:54 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:28:54 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:29:09 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:29:11 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:29:16 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:29:24 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:29:40 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:30:09 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:30:09 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:30:25 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:30:27 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:30:31 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:30:39 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:30:56 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:31:25 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:31:25 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:31:40 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:31:43 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:31:55 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:32:11 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:32:40 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:32:40 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:32:56 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:33:02 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:33:27 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:33:56 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:33:56 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:34:17 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:35:11 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:35:11 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:35:26 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:35:32 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:36:26 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:36:26 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:36:41 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:36:48 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:36:56 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:37:12 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:37:41 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:37:41 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:37:57 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:37:59 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:38:11 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:38:27 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:38:56 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
May 22 16:38:56 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS Error: TLS handshake failed
May 22 16:39:12 vpn-otp openvpn[70797]: read UDPv4 [ECONNREFUSED]: Connection refused (fd=7,code=111)
May 22 16:39:13 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 TLS: tls_multi_process: killed expiring key
May 22 16:39:13 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 No encryption key found. Purging data channel keys
May 22 16:39:13 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 dco_del_key: netlink reports object not found, ovpn-dco unloaded?
May 22 16:39:13 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 dco_del_key: failed to send netlink message: No such file or directory (-2)
May 22 16:39:13 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 Cannot delete primary key during wipe: No such file or directory (-2)
May 22 16:39:13 vpn-otp openvpn[70797]: testuser/10.8.23.133:53401 SIGUSR1[soft,dco update keys error] received, client-instance restarting
May 22 16:39:13 vpn-otp openvpn[70797]: dco_del_peer: netlink reports object not found, ovpn-dco unloaded?
May 22 16:39:13 vpn-otp openvpn[70797]: dco_del_peer: failed to send netlink message: No such file or directory (-2)

Anthony.

ordex commented 1 year ago

Thanks Anthony. I can't spot anything interesting in the log, however, the fact that it's so easy for you to reproduce this issue means that your setup must have some required bit.

I will check the code and let you know what else we can try to debug this.

schwabe commented 1 year ago

@ordex I think that version of connect client does not support the cc exit notification.

ordex commented 1 year ago

@ordex I think that version of connect client does not support the cc exit notification.

yeah, probably still sending over the data channel. But that's not important for this bug. Here the DEL_PEER notification is unable to bubble up to userspace due to netlink returning NLE_AGAIN. Pretty weird.

atoy40 commented 1 year ago

@schwabe Yes it's probably the case, but it does not explain the ping timeout problem and the netlink TRYAGAIN error

atoy40 commented 1 year ago

@ordex When searching about this NL error, I've seen some NetworkManager code that loop while it get the NLE_AGAIN :

do {
    errno = 0;

    nle = nl_recvmsgs (sk, cb);

    /* Work around a libnl bug fixed in 3.2.22 (375a6294) */
    if (nle == 0 && (errno == EAGAIN || errno == EWOULDBLOCK))
        nle = -NLE_AGAIN;
} while (nle != -NLE_AGAIN);

I don't know if it is a good practice or if it call help... but never know :)

atoy40 commented 1 year ago

oh or not ... I miss the != :)

ordex commented 1 year ago

Yeah this is fixing something else 🤓 @schwabe any clue why the socket would be ready to read but then recvmsg would return EAGAIN ?

schwabe commented 1 year ago

@ordex sorry. Never looked really into the socket code that deep to figure out when EAGIN would be actually be thown.

atoy40 commented 1 year ago

@ordex I'm absolutely not a NL specialist, but when I read this code : https://github.com/sgros/MIF_NetworkManager/blob/master/src/platform/nm-linux-platform.c#L5800 It seems they do not really consider NLE_AGAIN as an error ? but again ... i'm far to understanding everything :)

Btw, I've launch my VPN server to a bunnch of users to test it in real life, and the NLE_AGAIN appears at least 90% of time.

Anthony

ordex commented 1 year ago

@atoy40 thanks for the pointer. That is indeed interesting. My experience is that if you don't handle it somehow, you may just end up ina busy loop with the read always returns EAGAIN. But this might be different in this context.

I'll give it a try.

Btw amazing how you can trigger this so often. On the other hand this is good so you can easily test a potential fix.

atoy40 commented 1 year ago

@ordex yes, if you think you've found a workarround, I'll can confirm in a minute :D

but if I put this little problem aside .... DCO is amazing :D users have seen perf improvements immediately and sessions are stables for hours to days. And the biggest improvement for us is the "split" of data and control. Cauze we are using management socket to plug our authentication mecanisms, and now this is not hanging data transfer anymore if problem occurs.

ordex commented 1 year ago

yesss, glad to hear that! All issues that DCO wanted to solve, indeed. Thanks for the feedback!

ordex commented 1 year ago

@atoy40 I have created a patch which simply ignores the NLE_AGAIN error and treat it as if nothing went wrong. I am unable to test as I can't reproduce this issue, but maybe you could give it a quick spin?

You can find the patched OpenVPN code in the antonio/nle_again branch (https://github.com/OpenVPN/openvpn/tree/antonio/nle_again)

Please let us know!

atoy40 commented 1 year ago

@ordex, just a question do you now where I can find debian source packages (or at least de debian folder used to make your build) ? It'll be easier for me to rebuild a deb package to install it in my test server, and I'll be sure to use the same build flags as the package from you repository (build.openvpn.net). This repository doesn't have source packages.

atoy40 commented 1 year ago

@ordex ... just find the openvpn-build git repo :) let's go .

atoy40 commented 1 year ago

@ordex I built the debian package using the tarball of your branch. What happen next is just this :

Jun 16 17:56:49 vpn-dco openvpn[34088]: dco_do_read: netlink reports EAGAIN - ignoring.
Jun 16 17:56:49 vpn-dco kernel: [19050.702475] dco1: deleting peer with id 0, reason 2

The error is ignored, but no more in the userspace program, the client is not removed.

I can add I tested it on a fresh debian bulleye install with only openvpn running and a very simple config (mode server, auth pam). I started/disconnected 10 connections, and 50% had the EAGAIN error.

Anthony.

ordex commented 1 year ago

May i know what HW is that? I'm truly unable to reproduce this issue.

On the other hand, having access to the system, in order to perform since tests, might be very helpful. Is that something you could arrange?

atoy40 commented 1 year ago

I've two different system, but both are KVM virtual machine with intel processors. No problem to give you an access, I'll prepare it tomorrow, If you can give me an ssh public key, I'll add it on the system.

Anthony.

ordex commented 1 year ago

@ordex I built the debian package using the tarball of your branch. What happen next is just this :

Jun 16 17:56:49 vpn-dco openvpn[34088]: dco_do_read: netlink reports EAGAIN - ignoring.
Jun 16 17:56:49 vpn-dco kernel: [19050.702475] dco1: deleting peer with id 0, reason 2

The error is ignored, but no more in the userspace program, the client is not removed.

I can add I tested it on a fresh debian bulleye install with only openvpn running and a very simple config (mode server, auth pam). I started/disconnected 10 connections, and 50% had the EAGAIN error.

Anthony.

so, as originally supposed, the NLE_AGAIN error is happening at the time of DEL_PEER delivery. Therefore that error is preventing to read the notification, hence ignoring it does not truly work.

ordex commented 1 year ago

I've two different system, but both are KVM virtual machine with intel processors. No problem to give you an access, I'll prepare it tomorrow, If you can give me an ssh public key, I'll add it on the system.

Anthony.

@atoy40 can you mail me at antonio@openvpn.net please, so we can exchange all details?

atoy40 commented 9 months ago

@ordex, Sorry I was on another project, but I restart working on our openvpn server. I reinstall it from scratch with debian 12 (my problems was with 11) and last stable openvpn/dco package .... no more netlink problems.

Thanks for your support !

ordex commented 9 months ago

Glad it's working, although we haven't changed anything 😁 But you were the only one having reported this...so for now we can consider the case closed. Thanks!