Opened 7 years ago

Last modified 2 years ago

#345 new Bug / Defect

management interface reports incorrect state after TLS handshake failure and renegotiation

Reported by: hart.mike@… Owned by:
Priority: minor Milestone:
Component: Management Version: OpenVPN 2.2.1 (Community Ed)
Severity: Not set (select this one, unless your'e a OpenVPN developer) Keywords:
Cc:

Description

OpenVPN 2.2.1 on Ubuntu 12.04, both clients and servers. VPN connections are over somewhat unreliable networks. We've seen this happen regularly over the past few weeks. Once we see an error like this, the "state" command on the management interface reports the incorrect state, and continues to do so until the client or server are restarted. The tunnel is up and functioning, just the management interface reports it wrong.

$ echo state | nc localhost 1151
>INFO:OpenVPN Management Interface Version 1 -- type 'help' for more info
1384405371,WAIT,,,
END

The expected output should be:

...
1384405371,CONNECTED,SUCCESS,10.42.1.2,1.2.3.4
END

Here's the log snippet (CA and IP's and hostnames changed to protect the innocent) of when it actually happened, until then the proper output was displayed. It appears the TLS re-negotiation failed at 05:02:36, then re-established the connection at 05:02:51.

Nov 14 04:01:35 vpn.client openvpn-inband[14143]: TLS: tls_process: killed expiring key
Nov 14 04:01:36 vpn.client openvpn-inband[14143]: TLS: soft reset sec=0 bytes=1837717/0 pkts=8844/0
Nov 14 04:01:36 vpn.client openvpn-inband[14143]: VERIFY OK: depth=2, /C=CA/O=My_Company/CN=Root_CA/emailAddress=certs@mycompany.com
Nov 14 04:01:36 vpn.client openvpn-inband[14143]: VERIFY OK: depth=1, /C=CA/O=My_Company/CN=Subordinate_CA/emailAddress=certs@mycompany.com
Nov 14 04:01:36 vpn.client openvpn-inband[14143]: VERIFY OK: depth=0, /C=CA/ST=/L=/O=My_Company/OU=/CN=vpn.server-server/emailAddress=pki@mycompany.com
Nov 14 04:01:36 vpn.client openvpn-inband[14143]: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Nov 14 04:01:36 vpn.client openvpn-inband[14143]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Nov 14 04:01:36 vpn.client openvpn-inband[14143]: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Nov 14 04:01:36 vpn.client openvpn-inband[14143]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Nov 14 04:01:36 vpn.client openvpn-inband[14143]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA
Nov 14 05:01:36 vpn.client openvpn-inband[14143]: TLS: soft reset sec=0 bytes=1909669/0 pkts=9129/0
Nov 14 05:02:36 vpn.client openvpn-inband[14143]: TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Nov 14 05:02:36 vpn.client openvpn-inband[14143]: TLS Error: TLS handshake failed
Nov 14 05:02:36 vpn.client openvpn-inband[14143]: TLS: move_session: dest=TM_LAME_DUCK src=TM_ACTIVE reinit_src=1
Nov 14 05:02:51 vpn.client openvpn-inband[14143]: TLS: Initial packet from [AF_INET]1.2.3.4:11194, sid=386f21f8 147b9048
Nov 14 05:02:51 vpn.client openvpn-inband[14143]: VERIFY OK: depth=2, /C=CA/O=My_Company/CN=Root_CA/emailAddress=certs@mycompany.com
Nov 14 05:02:51 vpn.client openvpn-inband[14143]: VERIFY OK: depth=1, /C=CA/O=My_Company/CN=Subordinate_CA/emailAddress=certs@mycompany.com
Nov 14 05:02:51 vpn.client openvpn-inband[14143]: VERIFY OK: depth=0, /C=CA/ST=/L=/O=My_Company/OU=/CN=vpn.server-server/emailAddress=pki@mycompany.com
Nov 14 05:02:52 vpn.client openvpn-inband[14143]: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
Nov 14 05:02:52 vpn.client openvpn-inband[14143]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Nov 14 05:02:52 vpn.client openvpn-inband[14143]: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
Nov 14 05:02:52 vpn.client openvpn-inband[14143]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
Nov 14 05:02:52 vpn.client openvpn-inband[14143]: Control Channel: TLSv1, cipher TLSv1/SSLv3 DHE-RSA-AES256-SHA, 2048 bit RSA

Client configuration file (with CA info and server IP changed)

ca /etc/ssl/certs/my-ca-chain.pem
cert /etc/openvpn/ssl/vpn.client.cert
key /etc/openvpn/ssl/vpn.client.key
client
remote 1.2.3.4
port 11194
proto udp
dev tap3
ping 10
ping-restart 60
persist-tun
persist-key
daemon openvpn-inband
comp-lzo
user nobody
group nogroup
verb 3
mssfix 1464
management 127.0.0.1 1151
script-security 2
up /etc/openvpn/vpn_up.sh
down /etc/openvpn/vpn_down.sh

And the corresponding server configuration:

ca /etc/ssl/certs/my-ca-chain.pem
cert /etc/openvpn/ssl/vpn.server-server.cert
key /etc/openvpn/ssl/vpn.server-server.key
dh /etc/openvpn/ssl/dh2048.pem
dev tap3
tls-server
server 10.42.1.0 255.255.255.0
topology subnet
port 1194
proto udp
max-clients 1
ping 10
ping-restart 120
persist-tun
persist-key
daemon openvpn-inband
comp-lzo
user nobody
group nogroup
verb 3
mssfix 1464
management 127.0.0.1 1151
script-security 2
up /etc/openvpn/vpnup.sh
client-connect /etc/openvpn/client_connect.sh
ifconfig-pool-persist /var/run/openvpn/clients.db 60

Change History (8)

comment:1 Changed 7 years ago by Samuli Seppänen

Could you try OpenVPN 2.3.2 or better yet, Git "master" (=latest development version)? We don't support 2.2.x anymore, except with very critical security patches. We provide official Debian/Ubuntu packages for OpenVPN 2.3.2 - for details look here.

comment:2 Changed 5 years ago by Samuli Seppänen

No activity in 19 months. Please test if this problem persists with the latest OpenVPN Git "master" version - otherwise we'll have to close this ticket.

comment:3 Changed 5 years ago by hummel99

Still happends sometimes with OpenVPN 2.3.8

comment:4 Changed 5 years ago by hummel99

Log when the State is WAIT after Connect:

Connected to localhost.localdomain (127.0.0.1).
Escape character is ']'.

INFO:OpenVPN Management Interface Version 1 -- type 'help' for more info

log all
1457295955,W,DEPRECATED OPTION: --tls-remote, please update your configuration
1457295955,I,OpenVPN 2.3.8 i686-pc-linux-gnu [SSL (OpenSSL)] [LZO] [EPOLL] [MH] [IPv6] built on Sep 19 2015
1457295955,I,library versions: OpenSSL 0.9.8ze 15 Jan 2015, LZO 2.03
1457295955,W,NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
1457295955,I,TUN/TAP device VPN10 opened
1457295955,I,UDPv4 link local (bound): [undef]
1457295955,I,UDPv4 link remote: [undef]
1457295956,N,TLS Error: local/remote TLS keys are out of sync: [AF_INET]IPADDRESS:1205 [1]
1457295957,N,TLS Error: local/remote TLS keys are out of sync: [AF_INET]IPADDRESS:1205 [1]
1457295958,N,TLS Error: local/remote TLS keys are out of sync: [AF_INET]IPADDRESS:1205 [1]
1457295958,N,TLS Error: local/remote TLS keys are out of sync: [AF_INET]IPADDRESS:1205 [1]
1457295959,N,TLS Error: local/remote TLS keys are out of sync: [AF_INET]IPADDRESS:1205 [1]
1457295960,N,TLS Error: local/remote TLS keys are out of sync: [AF_INET]IPADDRESS:1205 [1]
1457295961,N,TLS Error: local/remote TLS keys are out of sync: [AF_INET]IPADDRESS:1205 [1]
1457295964,I,[zsau01-zs01-pri-vpn00.tila.de] Peer Connection Initiated with [AF_INET]IPADDRESS:1205
1457295965,I,Initialization Sequence Completed
1457377769,I,[zsau01-zs01-pri-vpn00.tila.de] Inactivity timeout (--ping-restart), restarting
1457377769,I,/root/kerbynet.cgi/scripts/vpn_mii VPN10 1500 1573 init
1457377769,I,SIGUSR1[soft,ping-restart] received, process restarting
1457377771,W,NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
1457377771,I,TUN/TAP device VPN10 opened
1457377771,I,UDPv4 link local (bound): [undef]
1457377771,I,UDPv4 link remote: [undef]
1457377782,I,[UNDEF] Inactivity timeout (--ping-restart), restarting
1457377782,I,/root/kerbynet.cgi/scripts/vpn_mii VPN10 1500 1573 init
1457377782,I,SIGUSR1[soft,ping-restart] received, process restarting
1457377784,W,NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
1457377784,I,TUN/TAP device VPN10 opened
1457377784,I,UDPv4 link local (bound): [undef]
1457377784,I,UDPv4 link remote: [undef]
1457377795,I,[UNDEF] Inactivity timeout (--ping-restart), restarting
1457377795,I,/root/kerbynet.cgi/scripts/vpn_mii VPN10 1500 1573 init
1457377795,I,SIGUSR1[soft,ping-restart] received, process restarting
1457377797,W,NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
1457377797,I,TUN/TAP device VPN10 opened
1457377797,I,UDPv4 link local (bound): [undef]
1457377797,I,UDPv4 link remote: [undef]
1457377808,I,[UNDEF] Inactivity timeout (--ping-restart), restarting
1457377808,I,/root/kerbynet.cgi/scripts/vpn_mii VPN10 1500 1573 init
1457377808,I,SIGUSR1[soft,ping-restart] received, process restarting
1457377810,W,NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
1457377810,I,TUN/TAP device VPN10 opened
1457377810,I,UDPv4 link local (bound): [undef]
1457377810,I,UDPv4 link remote: [undef]
1457377821,I,[UNDEF] Inactivity timeout (--ping-restart), restarting
1457377821,I,/root/kerbynet.cgi/scripts/vpn_mii VPN10 1500 1573 init
1457377821,I,SIGUSR1[soft,ping-restart] received, process restarting
1457377823,W,NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
1457377823,I,TUN/TAP device VPN10 opened
1457377823,I,UDPv4 link local (bound): [undef]
1457377823,I,UDPv4 link remote: [undef]
1457377834,I,[UNDEF] Inactivity timeout (--ping-restart), restarting
1457377834,I,/root/kerbynet.cgi/scripts/vpn_mii VPN10 1500 1573 init
1457377834,I,SIGUSR1[soft,ping-restart] received, process restarting
1457377836,W,NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
1457377836,I,TUN/TAP device VPN10 opened
1457377836,I,UDPv4 link local (bound): [undef]
1457377836,I,UDPv4 link remote: [undef]
1457377847,I,[UNDEF] Inactivity timeout (--ping-restart), restarting
1457377847,I,/root/kerbynet.cgi/scripts/vpn_mii VPN10 1500 1573 init
1457377847,I,SIGUSR1[soft,ping-restart] received, process restarting
1457377849,W,NOTE: the current --script-security setting may allow this configuration to call user-defined scripts
1457377849,I,TUN/TAP device VPN10 opened
1457377849,I,UDPv4 link local (bound): [undef]
1457377849,I,UDPv4 link remote: [undef]
1457377858,I,[FQDN] Peer Connection Initiated with [AF_INET]IPADDRESS:1205
1457377859,I,Initialization Sequence Completed
END

comment:5 Changed 5 years ago by hummel99

Connected to localhost.localdomain (127.0.0.1).
Escape character is ']'.

INFO:OpenVPN Management Interface Version 1 -- type 'help' for more info

state
1457377859,WAIT,
END

comment:6 Changed 5 years ago by Samuli Seppänen

hummel99: can you reproduce this issue with latest Git "master"? Lots of things are different there.

comment:7 Changed 5 years ago by hummel99

I don' know which situation causes this behaviour, as I read in the docs the WAIT state should be only possible with clients, but the log is from a server daemon. Any idea how to force this situation?

comment:8 Changed 2 years ago by Symon

This bug is still present with OpenVPN 2.4.4 in pfSense 2.4.1. This happens often (after a few hours) on less reliable links using TLS "Encryption and Authentication mode also encrypts control channel communication, providing more privacy and traffic control channel obfuscation." This particular site-to-site link goes from USA (client) to China(server), which is why all the TLS is turned on and explains why it is a little unreliable. xxx is USA IP address, yyy is China.
Here's the pfSense logging at the Server end (most recent at top):-

Jul 17 08:45:30   openvpn   23984   [USAToChinaClient] Peer Connection Initiated with [AF_INET]xxx.xxx.xxx.xxx:7575
Jul 17 08:45:29   openvpn   23984   WARNING: 'ifconfig' is present in local config but missing in remote config, local='ifconfig 10.1.71.1 10.1.71.2'
Jul 17 08:45:29   openvpn   23984   peer info: IV_TCPNL=1
Jul 17 08:45:29   openvpn   23984   peer info: IV_COMP_STUBv2=1
Jul 17 08:45:29   openvpn   23984   peer info: IV_COMP_STUB=1
Jul 17 08:45:29   openvpn   23984   peer info: IV_LZO=1
Jul 17 08:45:29   openvpn   23984   peer info: IV_LZ4v2=1
Jul 17 08:45:29   openvpn   23984   peer info: IV_LZ4=1
Jul 17 08:45:29   openvpn   23984   peer info: IV_NCP=2
Jul 17 08:45:29   openvpn   23984   peer info: IV_PROTO=2
Jul 17 08:45:29   openvpn   23984   peer info: IV_PLAT=freebsd
Jul 17 08:45:29   openvpn   23984   peer info: IV_VER=2.4.4
Jul 17 08:45:25   openvpn   23984   TLS Error: TLS handshake failed
Jul 17 08:45:25   openvpn   23984   TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Jul 17 08:30:57   openvpn   23984   Initialization Sequence Completed 

Here's the server conf file:-

[2.4.1-RELEASE][root@ch-pfSense.??????.com]/var/etc/openvpn: cat server15.conf
dev ovpns15
verb 1
dev-type tun
dev-node /dev/tun15
writepid /var/run/openvpn_server15.pid
#user nobody
#group nobody
script-security 3
daemon
keepalive 10 60
ping-timer-rem
persist-tun
persist-key
proto udp4
cipher AES-128-CBC
auth SHA1
up /usr/local/sbin/ovpn-linkup
down /usr/local/sbin/ovpn-linkdown
local yyy.yyy.yyy.yyy
tls-server
ifconfig 10.1.71.1 10.1.71.2
lport <redacted>
management /var/etc/openvpn/server15.sock unix
max-clients 16
push "route 192.168.68.0 255.255.255.0"
route 192.168.192.0 255.255.252.0
ca /var/etc/openvpn/server15.ca 
cert /var/etc/openvpn/server15.cert 
key /var/etc/openvpn/server15.key 
dh /etc/dh-parameters.2048
tls-crypt /var/etc/openvpn/server15.tls-crypt 
ncp-ciphers AES-256-GCM:AES-128-GCM

Here's the OpenVPN version:-

[2.4.1-RELEASE][root@ch-pfSense.??????.com]/var/etc/openvpn: openvpn --help
OpenVPN 2.4.4 amd64-portbld-freebsd11.1 [SSL (OpenSSL)] [LZO] [LZ4] [MH/RECVDA] [AEAD] built on Oct 19 2017

Here's the management report:-

[2.4.1-RELEASE][root@ch-pfSense.???????.com]/var/etc/openvpn:  nc -U /var/etc/openvpn/server15.sock
>INFO:OpenVPN Management Interface Version 1 -- type 'help' for more info
state
1531817128,WAIT,,,,,,
END
^C

The upshot is that the pfSense GUI shows a blank line where it normally reports the server status. Also, my Zabbix monitoring system report the link down, even though it's actually working because it uses the management interface. I can do further debugging anyone can guide me.
Thanks, Symon.

Last edited 2 years ago by Symon (previous) (diff)
Note: See TracTickets for help on using tickets.