Opened 10 years ago
Last modified 6 years ago
#345 new Bug / Defect
management interface reports incorrect state after TLS handshake failure and renegotiation
| Reported by: | 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 10 years ago by
comment:2 Changed 9 years ago by
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:4 Changed 8 years ago by
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 8 years ago by
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 8 years ago by
hummel99: can you reproduce this issue with latest Git "master"? Lots of things are different there.
comment:7 Changed 8 years ago by
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 6 years ago by
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:-
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.
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.