Daily Disconnection Issue

[chrismcv]

Hi,
I currently have an issue on one of my openvpn servers where users are being kicked out at roughly the same time every day. I'm trying to analyse the issue, and not seeing anything obvious that is causing the problems.

There are around 100 clients simultaneously connected to the VPN. CPU Load is low. The server is one of 5 connected to the same switch, and is the only one affected. Server time is in sync with the client time reasonably well.

Any help would be much appreciated.

Server Conf

Code: Select all

daemon openvpnserver
writepid /var/run/openvpn.pid
#DAN prepare ZERINA for listening on blue and orange
dev tun
tun-mtu 1500
proto udp
port 1194
tls-server
ca /var/ipcop/ovpn/ca/cacert.pem
cert /var/ipcop/ovpn/certs/servercert.pem
key /var/ipcop/ovpn/certs/serverkey.pem
dh /var/ipcop/ovpn/ca/dh1024.pem
server 10.13.0.0 255.255.0.0
push "route 10.1.3.0 255.255.255.0"
keepalive 10 60
status-version 1
status /var/log/ovpnserver.log 30
cipher BF-CBC
comp-lzo
max-clients 200
client-config-dir /var/ipcop/ovpn/ccd
ccd-exclusive
fast-io
mtu-disc yes
mssfix 1300
tls-verify /var/ipcop/ovpn/verify
crl-verify /var/ipcop/ovpn/crls/cacrl.pem
user nobody
group nobody
persist-key
persist-tun
verb 3

Client Conf

Code: Select all

#OpenVPN Server conf
tls-client
client
dev tun
proto udp
tun-mtu 1500
mssfix 1300
remote IP 1194
pkcs12 mycert.p12
cipher BF-CBC
comp-lzo
verb 3
ns-cert-type server

I've included a server log output of what is happening. [in reverse chronological order]

Code: Select all

12:52:29 openvpnserver MYCERT/IP:PORT Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 1024 bit RSA
12:52:29 openvpnserver MYCERT/IP:PORT Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
12:52:29 openvpnserver MYCERT/IP:PORT Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
12:52:29 openvpnserver MYCERT/IP:PORT Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
12:52:29 openvpnserver MYCERT/IP:PORT Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
12:52:29 openvpnserver MYCERT/IP:PORT VERIFY OK: depth=0, ...
12:52:29 openvpnserver MYCERT/IP:PORT CRL CHECK OK: ...
12:52:29 openvpnserver MYCERT/IP:PORT VERIFY SCRIPT OK: depth=0, ... 
12:52:29 openvpnserver MYCERT/IP:PORT VERIFY OK: depth=1, ... 
12:52:29 openvpnserver MYCERT/IP:PORT CRL CHECK OK: ...
12:52:29 openvpnserver MYCERT/IP:PORT VERIFY SCRIPT OK: depth=1, ... 
... 2 minutes of repeating the messages below...

12:50:59 openvpnserver MYCERT/IP:PORT TLS Error: Unroutable control packet received from IP:PORT (si=3 op=P_ACK_V1)
12:50:57 openvpnserver MYCERT/IP:PORT TLS Error: Unroutable control packet received from IP:PORT (si=3 op=P_ACK_V1)
12:50:55 openvpnserver MYCERT/IP:PORT TLS: Initial packet from IP:PORT, sid=935383e5 98786ad3
12:50:54 openvpnserver MYCERT/IP:PORT TLS Error: TLS handshake failed
12:50:54 openvpnserver MYCERT/IP:PORT TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
12:50:54 openvpnserver MYCERT/IP:PORT TLS Error: TLS handshake failed
12:50:54 openvpnserver MYCERT/IP:PORT TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
12:50:54 openvpnserver MYCERT/IP:PORT TLS Error: reading acknowledgement record from packet
12:50:51 openvpnserver MYCERT/IP:PORT TLS Error: reading acknowledgement record from packet
12:50:46 openvpnserver MYCERT/IP:PORT TLS Error: reading acknowledgement record from packet
12:50:43 openvpnserver MYCERT/IP:PORT TLS Error: Unroutable control packet received from IP:PORT (si=3 op=P_ACK_V1)
12:50:43 openvpnserver MYCERT/IP:PORT TLS Error: reading acknowledgement record from packet
12:50:42 openvpnserver MYCERT/IP:PORT TLS Error: reading acknowledgement record from packet
12:50:42 openvpnserver MYCERT/IP:PORT TLS Error: reading acknowledgement record from packet
12:50:39 openvpnserver MYCERT/IP:PORT TLS Error: reading acknowledgement record from packet
12:50:28 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS Error: reading acknowledgement record from packet
12:50:24 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS Error: reading acknowledgement record from packet
12:50:24 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS Error: Unroutable control packet received from IP:PORT (si=3 op=P_ACK_V1)
12:50:24 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:24 openvpnserver MYCERT/IP:PORT TLS Error: reading acknowledgement record from packet
12:50:23 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT
12:50:21 openvpnserver MYCERT/IP:PORT TLS: Initial packet from IP:PORT, sid=a0951711 13be7aab
12:49:53 openvpnserver MYCERT/IP:PORT TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1
12:49:53 openvpnserver MYCERT/IP:PORT TLS Error: TLS handshake failed
12:49:53 openvpnserver MYCERT/IP:PORT TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
12:49:53 openvpnserver MYCERT/IP:PORT TLS: new session incoming connection from IP:PORT

12:40:33 openvpnserver MYCERT/IP:PORT TLS: soft reset sec=-19 bytes=302668/0 pkts=2557/0

[Mimiko]

What kind of antivirus you run on the server?

[chrismcv]

There isn't an AV on the server - I'm using IPCOPs.

There is a small spike in disk activity about the same time - writing about 250 sectors per second for a few minutes - but I'm not sure if this is a symptom of lots of reconnections happening, or a cause.

[janjust]

the server log suggests that the TLS renegotiation is failing ; is there a firewall rule that is blocking certain types of states?

you can play with the TLS reneg parameters using

Code: Select all

--reneg-bytes n : Renegotiate data chan. key after n bytes sent and recvd.
--reneg-pkts n  : Renegotiate data chan. key after n packets sent and recvd.
--reneg-sec n   : Renegotiate data chan. key after n seconds (default=3600).
--hand-window n : Data channel key exchange must finalize within n seconds
                  of handshake initiation by any peer (default=60).

I'd set them much **shorter** initially to determine if that is indeed the cause of the problem.

[chrismcv]

My firewall does seem to have any such states in it.

And if it was a firewall issue, surely it would be more broadly affecting me, rather than once per day?

Code: Select all

root@fw-3:~ # iptables -L | grep udp
ACCEPT     udp  --  0.0.0.0/0            0.0.0.0/0           udp spt:500 dpt:500
ACCEPT     udp  --  0.0.0.0/0            0.0.0.0/0           udp dpt:4500
ACCEPT     udp  --  0.0.0.0/0            0.0.0.0/0           udp dpt:1194
LOG        udp  --  0.0.0.0/0            0.0.0.0/0           limit: avg 10/min burst 5 LOG flags 0 level 4 prefix `UDP Scan? '
ACCEPT     udp  --  0.0.0.0/0            IP       udp dpt:1194

And I can see re-negotiations happening happily every hour the rest of the day - so what will shortening the window achieve?

[Mimiko]

I will start by checking the processes running on this server. Something is interfering with packets transmitted thru phisical interface.

[janjust]

The log messages do suggest that it's a TLS reneg that is failing; why that is happening once per day I don't know. If you shorten the reneg window and it happens more often then you know it's related to the number of renegotiations. If the failed renegotiations still happen only once a day then you know it's something else.

your iptables rule rate limit UDP traffic (and log it) ; does anything show up in the iptables log file when these renegotiation errors occur? is a client trying to reconnect too fast ?