Home / server / Questions / 705984
In Process
nass
Asked: 2015-07-16 08:19:49 +0800 CST

TLS Error: Handshake failed. Openvpn Server is behind NAT on dynamic ip

  • 772

this is a common problem that appears easily in searches and seems to be related to the firewall , yet I can't seem to figure out how to fix it. I have actually asked before, but this time I come back with more info on the matter and a better understanding of the problem.

The problem appears when my openvpn server (which sits behind a NAT) has its external IP changed, since my internet connection has a dynamic ip.

SO, as soon as my external ip changes, my vpn clients can no longer connect to the server. It is a headache, because after a restart (of the openvpn server and perhaps the firewall as well) things usually are not corrected. After a few restarts though things will get working for a few days until my ip changes again.

The following logs have been acquired from 2 (server & a client) slackware linux systems.

My server config is the following:

cd /etc/openvpn
proto udp
port 32456
comp-lzo
verb 1
log-append /var/log/openvpn/server.log
status /var/log/openvpn/server-status.log
daemon
dev tun
persist-tun
persist-key
server 192.168.26.0 255.255.255.0
ifconfig-pool-persist /var/log/openvpn/ipp.txt
client-to-client
client-config-dir ccd
route-gateway 'dhcp'
route 192.168.114.0 255.255.255.0
route 192.168.18.0 255.255.255.0
push "route 192.168.112.0 255.255.255.0 vpn_gateway"
push "route 192.168.114.0 255.255.255.0"
push "route 192.168.18.0 255.255.255.0"
cipher BF-CBC
ca keys/ca.crt
dh keys/dh1024.pem
cert keys/stardust.crt
key keys/stardust.key
crl-verify certs/crl.pem
keepalive 20 120
user openvpn
group openvpn
max-clients 15

and the client config is the following (same across all clients)

client
dev tun
proto udp
remote my.dyndns1.site 32456
remote mydyndns2.site 32456
float
resolv-retry infinite
nobind
user nobody
group nobody
persist-key
persist-tun
ca /etc/openvpn/keys/ca.crt
cert /etc/openvpn/keys/forge.crt
key /etc/openvpn/keys/forge.key
ns-cert-type server
cipher BF-CBC
comp-lzo
verb 3
mute 10
keepalive 10 60
log-append /var/log/openvpn/client.log

on the server , the log files states the following ()

Mon Jul 13 17:27:43 2015 us=15365 x.x.x.x:39397 TLS Error: TLS key negotiation failed to occur within 60 seconds (check your network connectivity)
Mon Jul 13 17:27:43 2015 us=15406 x.x.x.x:39397 TLS Error: TLS handshake failed
....
....(a few seconds pass by)
....
Mon Jul 13 17:29:43 2015 us=15492 x.x.x.x:39397 SIGUSR1[soft,tls-error] received, client-instance restarting
Mon Jul 13 17:29:44 2015 us=718669 MULTI: multi_create_instance called
Mon Jul 13 17:29:44 2015 us=718735 x.x.x.x:47092 Re-using SSL/TLS context
Mon Jul 13 17:29:44 2015 us=718770 x.x.x.x:47092 LZO compression initialized
Mon Jul 13 17:29:44 2015 us=718856 x.x.x.x:47092 Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
Mon Jul 13 17:29:44 2015 us=718888 x.x.x.x:47092 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Mon Jul 13 17:29:44 2015 us=718932 x.x.x.x:47092 Local Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SH
A1,keysize 128,key-method 2,tls-server'
Mon Jul 13 17:29:44 2015 us=718948 x.x.x.x:47092 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-C
BC,auth SHA1,keysize 128,key-method 2,tls-client'
Mon Jul 13 17:29:44 2015 us=718974 x.x.x.x:47092 Local Options hash (VER=V4): '530fdded'
Mon Jul 13 17:29:44 2015 us=718994 x.x.x.x:47092 Expected Remote Options hash (VER=V4): '41690919'
Mon Jul 13 17:29:44 2015 us=719028 x.x.x.x:47092 TLS: Initial packet from x.x.x.x:47092, sid=a439532b 854729a0

on the client , the log file states:

Mon Jul 13 17:32:51 2015 us=341010 NOTE: OpenVPN 2.1 requires '--script-security 2' or higher to call user-defined scripts or executables
Mon Jul 13 17:32:51 2015 us=341263 Re-using SSL/TLS context
Mon Jul 13 17:32:51 2015 us=341309 LZO compression initialized
Mon Jul 13 17:32:51 2015 us=341451 Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
Mon Jul 13 17:32:51 2015 us=341526 Socket Buffers: R=[229376->131072] S=[229376->131072]
Mon Jul 13 17:32:51 2015 us=510459 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
Mon Jul 13 17:32:51 2015 us=510614 Local Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,keysize 128
,key-method 2,tls-client'
Mon Jul 13 17:32:51 2015 us=510642 Expected Remote Options String: 'V4,dev-type tun,link-mtu 1542,tun-mtu 1500,proto UDPv4,comp-lzo,cipher BF-CBC,auth SHA1,k
eysize 128,key-method 2,tls-server'
Mon Jul 13 17:32:51 2015 us=510692 Local Options hash (VER=V4): '41690919'
Mon Jul 13 17:32:51 2015 us=510733 Expected Remote Options hash (VER=V4): '530fdded'
Mon Jul 13 17:32:51 2015 us=510771 UDPv4 link local: [undef]
Mon Jul 13 17:32:51 2015 us=510806 UDPv4 link remote: [AF_INET]x.x.x.x:32456
....
....(a few secs pass by)
....
Mon Jul 13 17:32:49 2015 us=340411 [UNDEF] Inactivity timeout (--ping-restart), restarting
Mon Jul 13 17:32:49 2015 us=340678 TCP/UDP: Closing socket
Mon Jul 13 17:32:49 2015 us=340752 SIGUSR1[soft,ping-restart] received, process restarting
Mon Jul 13 17:32:49 2015 us=340792 Restart pause, 2 second(s)

do you see anything wrong with my configs? My guess is that the client firewalls do no allow ping-responses to reach them , once the ip of the server has changed (so all stateful ESTABLISH , RELATED connections no longer apply for the new server ip).

So looking into it I started testing the firewall logs and log the packets between a client and the openvpn server.

with tcpdump -i eth1 host <server_ip> and udp from the client side I checked the incoming packets ...

17:31:22.467092 IP 192.168.233.165.36312 > <server_ip>.32456: UDP, length 14
17:31:22.510463 IP <server_ip>.13519 > 192.168.233.165.36312: UDP, length 26
17:31:24.553394 IP 192.168.233.165.36312 > <server_ip>.32456: UDP, length 14
17:31:24.595869 IP <server_ip>.13519 > 192.168.233.165.36312: UDP, length 26

... while looking at the firewall log as well

Jul 15 17:31:22 zeus INPUT packet died: IN=eth1 OUT= MAC=00:50:bf:2b:5f:f8:20:89:86:9a:f1:10:08:00 SRC=<server_ip> DST=192.168.233.165 LEN=54 TOS=00 PREC=0x00 TTL=56 ID=0 DF PROTO=UDP SPT=13519 DPT=36312 LEN=34
Jul 15 17:31:24 zeus INPUT packet died: IN=eth1 OUT= MAC=00:50:bf:2b:5f:f8:20:89:86:9a:f1:10:08:00 SRC=<server_ip> DST=192.168.233.165 LEN=54 TOS=00 PREC=0x00 TTL=56 ID=0 DF PROTO=UDP SPT=13519 DPT=36312 LEN=34

Indeed, as per expected the connection is not established because the client firewall INPUT chain, intercepts the server's response. The client firewall looks like

iptables -A INPUT -p ALL -i $INET_IFACE -m state --state ESTABLISHED,RELATED -j ACCEPT

so I would expect this line to let the packet through. I do has stateful packet inspection enabled:

zcat /proc/config.gz | grep CONFIG_NF_CONNTRACK

CONFIG_NF_CONNTRACK=m
CONFIG_NF_CONNTRACK_MARK=y
# CONFIG_NF_CONNTRACK_EVENTS is not set
CONFIG_NF_CONNTRACK_IPV4=m
CONFIG_NF_CONNTRACK_IPV6=m
CONFIG_NETFILTER_NETLINK=m
CONFIG_NETFILTER_NETLINK_QUEUE=m
CONFIG_NETFILTER_NETLINK_LOG=m

just to verify I also checked

cat /proc/net/ip_conntrack | <server_ip>

udp 17 24 src=192.168.233.165 dst=<server_ip> sport=36312 dport=32456 [UNREPLIED] src=<server_ip> dst=192.168.233.165 sport=32456 dport=36312 mark=0 use=2

So reading the 2 first lines of tcpdump (taken from the client) the client sends a packet from port 36312 to the designated (in the openvpn server config) port 32456.

Then the client firewall setups up a conntrack rule (for established connection). This is not established yet - i assume the server must reply on the same channel .

BUT (reading back on the tcpdump, 2nd line) the openvpn server replies from port 13519, so this can never get passed the "ESTABLISHED,RELATED" lines.

Am I right to conclude that this is the problem? what can I do about this? There seems to be nothing available in the openvpn server to fix the server response port. And I am not sure about other possible solutions to this problem...

iptables

1 Answers

  1. Not really an answer, I know, I've just pasted my configs on OPs request.

    Client config:

    remote xxxx.no-ip.info
port 1195
float

# network
dev tun0
ifconfig 192.168.7.98 192.168.7.97
route 192.168.7.64 255.255.255.224 192.168.7.97
route 192.168.7.128 255.255.255.224 192.168.7.97

# symmetrical key
secret /etc/openvpn/scalpel/static.key

# compression
comp-lzo

# Security
user nobody
group nogroup

# high availability options
keepalive 10 30
persist-tun
persist-key
verb 1
mute 2

# Logging
log-append /var/log/openvpn_scalpel.log

    Server config:

    # Scalpel - OpenVPN Server (do lacznosci miedzy oddzialami)
# Last modified 2011.05.22

port 1195

# network
dev tun0
ifconfig 192.168.7.97 192.168.7.98
route 192.168.7.0 255.255.255.192 192.168.7.98

# symmetrical key
secret /etc/openvpn/scalpel/static.key

# compression
comp-lzo

# Security
user nobody
group nogroup
max-clients 1 # maximum number to clients allowed to connect

# high availability options
keepalive 10 30
persist-tun
persist-key
verb 1
mute 2

# Logging
log-append /var/log/openvpn_scalpel.log

    Packet trace server side:

      0.000000 79.184.15.251 -> 192.168.7.66 UDP 102 Source port: 5117  Destination port: 1195
  3.834972 192.168.7.66 -> 79.184.15.251 UDP 158 Source port: 1195  Destination port: 5117
  3.927502 79.184.15.251 -> 192.168.7.66 UDP 166 Source port: 5117  Destination port: 1195
  3.930257 192.168.7.66 -> 79.184.15.251 UDP 158 Source port: 1195  Destination port: 5117
  4.022063 79.184.15.251 -> 192.168.7.66 UDP 166 Source port: 5117  Destination port: 1195
  8.223466 79.184.15.251 -> 192.168.7.66 UDP 102 Source port: 5117  Destination port: 1195
 14.436576 192.168.7.66 -> 79.184.15.251 UDP 102 Source port: 1195  Destination port: 5117
 17.929467 79.184.15.251 -> 192.168.7.66 UDP 102 Source port: 5117  Destination port: 1195
 17.929594 79.184.15.251 -> 192.168.7.66 UDP 102 Source port: 5117  Destination port: 1195
 17.929685 192.168.7.66 -> 79.184.15.251 UDP 238 Source port: 1195  Destination port: 5117
 27.989889 192.168.7.66 -> 79.184.15.251 UDP 102 Source port: 1195  Destination port: 5117
 28.081743 79.184.15.251 -> 192.168.7.66 UDP 102 Source port: 5117  Destination port: 1195
 38.104471 192.168.7.66 -> 79.184.15.251 UDP 102 Source port: 1195  Destination port: 5117
 38.207144 79.184.15.251 -> 192.168.7.66 UDP 102 Source port: 5117  Destination port: 1195
 44.063394 79.184.15.251 -> 192.168.7.66 UDP 254 Source port: 5117  Destination port: 1195
 44.063662 79.184.15.251 -> 192.168.7.66 UDP 214 Source port: 5117  Destination port: 1195
 48.249463 192.168.7.66 -> 79.184.15.251 UDP 102 Source port: 1195  Destination port: 5117
 54.440786 79.184.15.251 -> 192.168.7.66 UDP 102 Source port: 5117  Destination port: 1195
 58.703483 192.168.7.66 -> 79.184.15.251 UDP 102 Source port: 1195  Destination port: 5117
Wed Jul 29 14:40:02 2015 read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
 68.715974 192.168.7.66 -> 79.184.15.251 UDP 102 Source port: 1195  Destination port: 5117
Wed Jul 29 14:40:12 2015 NOTE: --mute triggered...
 78.984871 192.168.7.66 -> 79.184.15.251 UDP 102 Source port: 1195  Destination port: 5117
Wed Jul 29 14:40:17 2015 1 variation(s) on previous 2 message(s) suppressed by --mute
Wed Jul 29 14:40:17 2015 Inactivity timeout (--ping-restart), restarting
Wed Jul 29 14:40:17 2015 SIGUSR1[soft,ping-restart] received, process restarting
Wed Jul 29 14:40:19 2015 NOTE: OpenVPN 2.1 requires '--script-security 2' or higher to call user-defined scripts or executables
Wed Jul 29 14:40:19 2015 Re-using pre-shared static key
Wed Jul 29 14:40:19 2015 LZO compression initialized
Wed Jul 29 14:40:19 2015 Preserving previous TUN/TAP instance: tun0
Wed Jul 29 14:40:19 2015 UDPv4 link local (bound): [undef]:1195
Wed Jul 29 14:40:19 2015 UDPv4 link remote: [undef]
Wed Jul 29 14:40:32 2015 Peer Connection Initiated with 79.184.15.251:5117
 99.482520 79.184.15.251 -> 192.168.7.66 UDP 102 Source port: 5117  Destination port: 1195
Wed Jul 29 14:40:33 2015 Initialization Sequence Completed
106.579960 192.168.7.66 -> 79.184.15.251 UDP 102 Source port: 1195  Destination port: 5117
106.579994 192.168.7.66 -> 79.184.15.251 UDP 102 Source port: 1195  Destination port: 5117
106.671790 79.184.15.251 -> 192.168.7.66 UDP 238 Source port: 5117  Destination port: 1195
110.199108 79.184.15.251 -> 192.168.7.66 UDP 102 Source port: 5117  Destination port: 1195
110.199228 192.168.7.66 -> 79.184.15.251 UDP 238 Source port: 1195  Destination port: 5117
119.683353 79.184.15.251 -> 192.168.7.66 UDP 102 Source port: 5117  Destination port: 1195
120.784617 192.168.7.66 -> 79.184.15.251 UDP 102 Source port: 1195  Destination port: 5117

    Packet trace client side:

      0.000000  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
  2.227622  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
  2.227651  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
  3.566194 89.69.145.76 -> 192.168.7.2  UDP Source port: 1195  Destination port: 1195
 11.640422  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
 13.809216 89.69.145.76 -> 192.168.7.2  UDP Source port: 1195  Destination port: 1195
Wed Jul 29 14:43:02 2015 read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
 21.876795  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
Wed Jul 29 14:43:12 2015 read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
 32.116168  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
Wed Jul 29 14:43:22 2015 NOTE: --mute triggered...
 42.283532  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
 42.283564  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
Wed Jul 29 14:43:24 2015 2 variation(s) on previous 2 message(s) suppressed by --mute
Wed Jul 29 14:43:24 2015 Inactivity timeout (--ping-restart), restarting
Wed Jul 29 14:43:24 2015 SIGUSR1[soft,ping-restart] received, process restarting
Wed Jul 29 14:43:26 2015 Re-using pre-shared static key
Wed Jul 29 14:43:26 2015 LZO compression initialized
Wed Jul 29 14:43:27 2015 Preserving previous TUN/TAP instance: tun0
Wed Jul 29 14:43:27 2015 UDPv4 link local (bound): [undef]:1195
Wed Jul 29 14:43:27 2015 UDPv4 link remote: 89.69.145.76:1195
Wed Jul 29 14:43:27 2015 read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Wed Jul 29 14:43:27 2015 read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
 46.575799  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
 46.575822  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
Wed Jul 29 14:43:31 2015 NOTE: --mute triggered...
 51.283850  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
 57.386083  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
 66.606426  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
 66.606450  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
Wed Jul 29 14:43:58 2015 4 variation(s) on previous 2 message(s) suppressed by --mute
Wed Jul 29 14:43:58 2015 Inactivity timeout (--ping-restart), restarting
Wed Jul 29 14:43:58 2015 SIGUSR1[soft,ping-restart] received, process restarting
 79.480353  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
Wed Jul 29 14:44:00 2015 Re-using pre-shared static key
Wed Jul 29 14:44:00 2015 LZO compression initialized
Wed Jul 29 14:44:00 2015 Preserving previous TUN/TAP instance: tun0
Wed Jul 29 14:44:00 2015 UDPv4 link local (bound): [undef]:1195
Wed Jul 29 14:44:00 2015 UDPv4 link remote: 89.69.145.76:1195
Wed Jul 29 14:44:00 2015 read UDPv4 [ECONNREFUSED]: Connection refused (code=111)
Wed Jul 29 14:44:10 2015 Peer Connection Initiated with 89.69.145.76:1195
 89.588295  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
 89.588321  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
 89.680566 89.69.145.76 -> 192.168.7.2  UDP Source port: 1195  Destination port: 1195
Wed Jul 29 14:44:11 2015 Initialization Sequence Completed
 92.180902 89.69.145.76 -> 192.168.7.2  UDP Source port: 1195  Destination port: 1195
 92.181072  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
 92.405420 89.69.145.76 -> 192.168.7.2  UDP Source port: 1195  Destination port: 1195
 92.405643  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
 92.409120 89.69.145.76 -> 192.168.7.2  UDP Source port: 1195  Destination port: 1195
 92.409194  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
 92.501167 89.69.145.76 -> 192.168.7.2  UDP Source port: 1195  Destination port: 1195
 92.501909  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195
 92.504901 89.69.145.76 -> 192.168.7.2  UDP Source port: 1195  Destination port: 1195
 92.505027  192.168.7.2 -> 89.69.145.76 UDP Source port: 1195  Destination port: 1195

    Both client and server are behind nat, both have dynamic public IP addresses. There is also a port forwarding (1195) on the router which connects server with the "World".

    Router config - server side:

    Router config

    Router config, port forwarding - server side:

    port forwarding

    Router config - client side:

    Client side router

    Conntrack client side:

    udp      17 179 src=192.168.7.2 dst=89.69.145.76 sport=1195 dport=1195 packets=852493 bytes=480026440 src=89.69.145.76 dst=192.168.7.2 sport=1195 dport=1195 packets=1093350 bytes=1226684584 [ASSURED] mark=0 use=1
    • 2