HMAC Error after clien sends Packages in wrong order (PID)

[CySlider]

Hi,

We encountered a really strange behaviour with OpenVPN 2.3.6 on CentOS 5. Some diveces of ours that are behind a SAT Link is having troubles getting through the buildup phase. We have hundreds of devices working fine since years so far.

But in this case for some strange reason it sends the packages not in the right order.

Sometimes it works. But its pure chance and chance varies over the day.
I think we can rule out firewall or connection issues, as this wrong sent packet order (from client to server) (...15, 17, 16, 17...) is already present in the openvpn logs on the client side.
If we switch to fiber connection everything is fine.
So currently our best shot is that some strange circumstance with the SAT Link connection triggers a bug in OpenVpn and it sends one packge early.

So two questions:

1) Why does the client send packet with PID=17 two times and for the first time, too early?

2) Why does the server not wait for the missing package and instead fails instantly with: "Authenticate/Decrypt packet error: packet HMAC authentication failed"?

Client Side: Notice PID series: 14, 15, 17, 16, 17, 18

Code: Select all

...
Apr 10 17:39:08 client openvpn[1300]: TCPv4_CLIENT WRITE [154] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #41 ] [ 39 ] pid=2 DATA len=100
Apr 10 17:39:08 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #42 ] [ ] pid=3 DATA len=100
Apr 10 17:39:08 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #43 ] [ ] pid=4 DATA len=100
Apr 10 17:39:08 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #44 ] [ ] pid=5 DATA len=100
Apr 10 17:39:09 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #45 ] [ ] pid=6 DATA len=100
Apr 10 17:39:10 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #46 ] [ ] pid=7 DATA len=100
Apr 10 17:39:10 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #47 ] [ ] pid=8 DATA len=100
Apr 10 17:39:10 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #48 ] [ ] pid=9 DATA len=100
Apr 10 17:39:10 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #49 ] [ ] pid=10 DATA len=100
Apr 10 17:39:11 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #50 ] [ ] pid=11 DATA len=100
Apr 10 17:39:11 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #51 ] [ ] pid=12 DATA len=100
Apr 10 17:39:11 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #52 ] [ ] pid=13 DATA len=100
Apr 10 17:39:12 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #53 ] [ ] pid=14 DATA len=100
Apr 10 17:39:12 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #54 ] [ ] pid=15 DATA len=100
Apr 10 17:39:13 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #55 ] [ ] pid=17 DATA len=100
Apr 10 17:39:13 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #56 ] [ ] pid=16 DATA len=100
Apr 10 17:39:13 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #57 ] [ ] pid=17 DATA len=100
Apr 10 17:39:13 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #58 ] [ ] pid=18 DATA len=100
Apr 10 17:39:14 client openvpn[1300]: TCPv4_CLIENT WRITE [142] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_V1 kid=0 pid=[ #59 ] [ ] pid=19 DATA len=100
Apr 10 17:39:20 client openvpn[1300]: TCPv4_CLIENT WRITE [42] to xxx.xxx.xxx.xxx:yyyy: P_CONTROL_HARD_RESET_CLIENT_V2 kid=0 pid=[ #1 ] [ ] pid=0 DATA len=0
Apr 10 17:39:20 client openvpn[1300]: TCPv4_CLIENT READ [54] from xxx.xxx.xxx.xxx:yyyy: P_CONTROL_HARD_RESET_SERVER_V2 kid=0 pid=[ #1 ] [ 0 ] pid=0 DATA len=0

Server side: Cancels on jump from PID=15 to 17

Code: Select all

...
Apr 10 19:39:09 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [154] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #41 ] [ 39 ] pid=2 DATA len=100
Apr 10 19:39:09 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #42 ] [ ] pid=3 DATA len=100
Apr 10 19:39:09 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #43 ] [ ] pid=4 DATA len=100
Apr 10 19:39:09 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #44 ] [ ] pid=5 DATA len=100
Apr 10 19:39:10 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #45 ] [ ] pid=6 DATA len=100
Apr 10 19:39:10 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #46 ] [ ] pid=7 DATA len=100
Apr 10 19:39:11 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #47 ] [ ] pid=8 DATA len=100
Apr 10 19:39:11 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #48 ] [ ] pid=9 DATA len=100
Apr 10 19:39:11 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #49 ] [ ] pid=10 DATA len=100
Apr 10 19:39:12 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #50 ] [ ] pid=11 DATA len=100
Apr 10 19:39:12 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #51 ] [ ] pid=12 DATA len=100
Apr 10 19:39:12 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #52 ] [ ] pid=13 DATA len=100
Apr 10 19:39:13 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #53 ] [ ] pid=14 DATA len=100
Apr 10 19:39:13 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #54 ] [ ] pid=15 DATA len=100
Apr 10 19:39:14 server openvpn[32482]: 192.168.19.253:48396 TCPv4_SERVER READ [142] from 192.168.19.253:48396: P_CONTROL_V1 kid=0 pid=[ #55 ] [ ] pid=17 DATA len=100
Apr 10 19:39:14 server openvpn[32482]: 192.168.19.253:48396 Authenticate/Decrypt packet error: packet HMAC authentication failed

Server Conf:

port yyyy
proto tcp
dev tun
ca ca.crt
tls-auth ta.key 0
cert ______________.com.crt
key ______________.com.key
dh dh2048.pem
server 172.20.0.0 255.255.0.0
client-config-dir clients
ifconfig-pool-persist ipp_server.txt
push "route 172.18.0.0 255.255.0.0"
keepalive 10 60
cipher AES-256-CBC
comp-lzo
max-clients 5000
user nobody
group nobody
persist-key
persist-tun
status status.log
verb 8

Client Conf:

client
dev tun0
proto tcp
remote xxx.xxx.xxx.xxx yyyy
resolv-retry infinite
persist-key
persist-tun
ca ca.crt
cert _________.crt
key _________.key
tls-auth ta.key 1
cipher AES-256-CBC
ns-cert-type server
verb 8

[Traffic]

1) Why does the client send packet with PID=17 two times and for the first time, too early?

UDP is a connectionless protocol and packets can arrive out of order ..

The problem is caused by the lack of --comp-lzo in your client.

[Traffic]

Ha .. just spotted it is TCP .. but still comp-lzo is the real problem.